Merge pull request #6747 from murgatroid99/node_logger_customization

Allow Node users to set a custom logger and log verbosity.

ext/node_grpc.cc

@@ -31,12 +31,16 @@
  *
  */
 
+#include <list>
+
 #include <node.h>
 #include <nan.h>
 #include <v8.h>
 #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<log_args *> *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<Object> exports) {
@@ -235,6 +257,18 @@ void InitWriteFlags(Local<Object> exports) {
   Nan::Set(write_flags, Nan::New("NO_COMPRESS").ToLocalChecked(), NO_COMPRESS);
 }
 
+void InitLogConstants(Local<Object> exports) {
+  Nan::HandleScope scope;
+  Local<Object> log_verbosity = Nan::New<Object>();
+  Nan::Set(exports, Nan::New("logVerbosity").ToLocalChecked(), log_verbosity);
+  Local<Value> DEBUG(Nan::New<Uint32, uint32_t>(GPR_LOG_SEVERITY_DEBUG));
+  Nan::Set(log_verbosity, Nan::New("DEBUG").ToLocalChecked(), DEBUG);
+  Local<Value> INFO(Nan::New<Uint32, uint32_t>(GPR_LOG_SEVERITY_INFO));
+  Nan::Set(log_verbosity, Nan::New("INFO").ToLocalChecked(), INFO);
+  Local<Value> ERROR(Nan::New<Uint32, uint32_t>(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<log_args *> 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<Value> file = Nan::New(arg->core_args.file).ToLocalChecked();
+    Local<Value> line = Nan::New<Uint32, uint32_t>(arg->core_args.line);
+    Local<Value> severity = Nan::New(
+        gpr_log_severity_string(arg->core_args.severity)).ToLocalChecked();
+    Local<Value> message = Nan::New(arg->core_args.message).ToLocalChecked();
+    Local<Value> timestamp = Nan::New<v8::Date>(
+        grpc::node::TimespecToMilliseconds(arg->timestamp)).ToLocalChecked();
+    const int argc = 5;
+    Local<Value> 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<log_args *>();
+  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<v8::Function>());
+}
+
+NAN_METHOD(SetLogVerbosity) {
+  if (!info[0]->IsUint32()) {
+    return Nan::ThrowTypeError(
+        "setLogVerbosity's argument must be a number");
+  }
+  gpr_log_severity severity = static_cast<gpr_log_severity>(
+      Nan::To<uint32_t>(info[0]).FromJust());
+  gpr_set_log_verbosity(severity);
+}
+
 void init(Local<Object> 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<Object> exports) {
            Nan::GetFunction(
                Nan::New<FunctionTemplate>(SetDefaultRootsPem)
                             ).ToLocalChecked());
+  Nan::Set(exports, Nan::New("setDefaultLoggerCallback").ToLocalChecked(),
+           Nan::GetFunction(
+               Nan::New<FunctionTemplate>(SetDefaultLoggerCallback)
+                            ).ToLocalChecked());
+  Nan::Set(exports, Nan::New("setLogVerbosity").ToLocalChecked(),
+           Nan::GetFunction(
+               Nan::New<FunctionTemplate>(SetLogVerbosity)
+                            ).ToLocalChecked());
 }
 
 NODE_MODULE(grpc_node, init)

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
  */

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);
+  }
+};

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;
       }

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);