Allow logging mechanism to be overridden by applications.

This necessitated the removal of gpr_vlog to keep a clean interface.
	Change on 2015/01/09 by ctiller <ctiller@google.com>
-------------
Created by MOE: http://code.google.com/p/moe-java
MOE_MIGRATED_REVID=83634996

include/grpc/support/log.h

@@ -72,9 +72,21 @@ const char *gpr_log_severity_string(gpr_log_severity severity);
 void gpr_log(const char *file, int line, gpr_log_severity severity,
              const char *format, ...);
 
-/* Same as above, but using a va_list instead. */
-void gpr_vlog(const char *file, int line, gpr_log_severity severity,
-              const char *format, va_list args);
+void gpr_log_message(const char *file, int line, gpr_log_severity severity,
+                     const char *message);
+
+/* Log overrides: applications can use this API to intercept logging calls
+   and use their own implementations */
+
+typedef struct {
+  const char *file;
+  int line;
+  gpr_log_severity severity;
+  const char *message;
+} gpr_log_func_args;
+
+typedef void (*gpr_log_func)(gpr_log_func_args *args);
+void gpr_set_log_function(gpr_log_func func);
 
 /* abort() the process if x is zero, having written a line to the log.
 

src/core/channel/connected_channel.c

@@ -289,12 +289,8 @@ static void accept_stream(void *user_data, grpc_transport *transport,
 }
 
 static void recv_error(channel_data *chand, call_data *calld, int line,
-                       const char *fmt, ...) {
-  va_list a;
-
-  va_start(a, fmt);
-  gpr_vlog(__FILE__, line, GPR_LOG_SEVERITY_ERROR, fmt, a);
-  va_end(a);
+                       const char *message) {
+  gpr_log_message(__FILE__, line, GPR_LOG_SEVERITY_ERROR, message);
 
   if (chand->transport) {
     grpc_transport_abort_stream(chand->transport,
@@ -388,19 +384,23 @@ static void recv_batch(void *user_data, grpc_transport *transport,
       case GRPC_OP_BEGIN_MESSAGE:
         /* can't begin a message when we're still reading a message */
         if (calld->reading_message) {
-          recv_error(chand, calld, __LINE__,
-                     "Message terminated early; read %d bytes, expected %d",
-                     calld->incoming_message.length,
-                     calld->incoming_message_length);
+          char message[128];
+          sprintf(message,
+                  "Message terminated early; read %d bytes, expected %d",
+                  (int)calld->incoming_message.length,
+                  (int)calld->incoming_message_length);
+          recv_error(chand, calld, __LINE__, message);
           return;
         }
         /* stash away parameters, and prepare for incoming slices */
         length = stream_op->data.begin_message.length;
         if (length > calld->max_message_length) {
-          recv_error(
-              chand, calld, __LINE__,
+          char message[128];
+          sprintf(
+              message,
               "Maximum message length of %d exceeded by a message of length %d",
               calld->max_message_length, length);
+          recv_error(chand, calld, __LINE__, message);
         } else if (length > 0) {
           calld->reading_message = 1;
           calld->incoming_message_length = length;
@@ -423,10 +423,12 @@ static void recv_batch(void *user_data, grpc_transport *transport,
         gpr_slice_buffer_add(&calld->incoming_message, stream_op->data.slice);
         if (calld->incoming_message.length > calld->incoming_message_length) {
           /* if we got too many bytes, complain */
-          recv_error(chand, calld, __LINE__,
-                     "Receiving message overflow; read %d bytes, expected %d",
-                     calld->incoming_message.length,
-                     calld->incoming_message_length);
+          char message[128];
+          sprintf(message,
+                  "Receiving message overflow; read %d bytes, expected %d",
+                  (int)calld->incoming_message.length,
+                  (int)calld->incoming_message_length);
+          recv_error(chand, calld, __LINE__, message);
           return;
         } else if (calld->incoming_message.length ==
                    calld->incoming_message_length) {
@@ -439,10 +441,11 @@ static void recv_batch(void *user_data, grpc_transport *transport,
                                  final_state == GRPC_STREAM_CLOSED)) {
     calld->got_read_close = 1;
     if (calld->reading_message) {
-      recv_error(chand, calld, __LINE__,
-                 "Last message truncated; read %d bytes, expected %d",
-                 calld->incoming_message.length,
-                 calld->incoming_message_length);
+      char message[128];
+      sprintf(message, "Last message truncated; read %d bytes, expected %d",
+              (int)calld->incoming_message.length,
+              (int)calld->incoming_message_length);
+      recv_error(chand, calld, __LINE__, message);
     }
     call_op.type = GRPC_RECV_HALF_CLOSE;
     call_op.dir = GRPC_CALL_UP;

src/core/support/log.c

@@ -34,6 +34,10 @@
 #include <grpc/support/log.h>
 
 #include <stdio.h>
+#include <string.h>
+
+extern void gpr_default_log(gpr_log_func_args *args);
+static gpr_log_func g_log_func = gpr_default_log;
 
 const char *gpr_log_severity_string(gpr_log_severity severity) {
   switch (severity) {
@@ -47,12 +51,15 @@ const char *gpr_log_severity_string(gpr_log_severity severity) {
   return "UNKNOWN";
 }
 
-void gpr_log(const char *file, int line, gpr_log_severity severity,
-             const char *format, ...) {
-  va_list args;
-  va_start(args, format);
-
-  gpr_vlog(file, line, severity, format, args);
-
-  va_end(args);
+void gpr_log_message(const char *file, int line, gpr_log_severity severity,
+                     const char *message) {
+  gpr_log_func_args lfargs;
+  memset(&lfargs, 0, sizeof(lfargs));
+  lfargs.file = file;
+  lfargs.line = line;
+  lfargs.severity = severity;
+  lfargs.message = message;
+  g_log_func(&lfargs);
 }
+
+void gpr_set_log_function(gpr_log_func f) { g_log_func = f; }

src/core/support/log_android.c

@@ -54,25 +54,31 @@ static android_LogPriority severity_to_log_priority(gpr_log_severity severity) {
   return ANDROID_LOG_DEFAULT;
 }
 
-void gpr_vlog(const char *file, int line, gpr_log_severity severity,
-              const char *format, va_list args) {
+void gpr_log(const char *file, int line, gpr_log_severity severity,
+             const char *format, ...) {
+  char *message = NULL;
+  va_list args;
+  va_start(args, format);
+  vasprintf(&message, format, args);
+  va_end(args);
+  gpr_log_message(file, line, severity, message);
+  free(message);
+}
+
+void gpr_default_log(gpr_log_func_args *args) {
   char *final_slash;
   const char *display_file;
-  char *prefix = NULL;
-  char *suffix = NULL;
   char *output = NULL;
 
-  final_slash = strrchr(file, '/');
+  final_slash = strrchr(args->file, '/');
   if (final_slash == NULL)
     display_file = file;
   else
     display_file = final_slash + 1;
 
-  asprintf(&prefix, "%s:%d] ", display_file, line);
-  vasprintf(&suffix, format, args);
-  asprintf(&output, "%s%s", prefix, suffix);
+  asprintf(&prefix, "%s:%d] %s", display_file, args->line, args->message);
 
-  __android_log_write(severity_to_log_priority(severity), "GRPC", output);
+  __android_log_write(severity_to_log_priority(args->severity), "GRPC", output);
 
   /* allocated by asprintf => use free, not gpr_free */
   free(prefix);

src/core/support/log_linux.c

@@ -49,17 +49,27 @@
 
 static long gettid() { return syscall(__NR_gettid); }
 
-void gpr_vlog(const char *file, int line, gpr_log_severity severity,
-              const char *format, va_list args) {
+void gpr_log(const char *file, int line, gpr_log_severity severity,
+             const char *format, ...) {
+  char *message = NULL;
+  va_list args;
+  va_start(args, format);
+  vasprintf(&message, format, args);
+  va_end(args);
+  gpr_log_message(file, line, severity, message);
+  free(message);
+}
+
+void gpr_default_log(gpr_log_func_args *args) {
   char *final_slash;
   const char *display_file;
   char time_buffer[64];
   gpr_timespec now = gpr_now();
   struct tm tm;
 
-  final_slash = strrchr(file, '/');
+  final_slash = strrchr(args->file, '/');
   if (final_slash == NULL)
-    display_file = file;
+    display_file = args->file;
   else
     display_file = final_slash + 1;
 
@@ -70,12 +80,10 @@ void gpr_vlog(const char *file, int line, gpr_log_severity severity,
     strcpy(time_buffer, "error:strftime");
   }
 
-  flockfile(stderr);
-  fprintf(stderr, "%s%s.%09d %7ld %s:%d] ", gpr_log_severity_string(severity),
-          time_buffer, (int)(now.tv_nsec), gettid(), display_file, line);
-  vfprintf(stderr, format, args);
-  fputc('\n', stderr);
-  funlockfile(stderr);
+  fprintf(stderr, "%s%s.%09d %7ld %s:%d] %s\n",
+          gpr_log_severity_string(args->severity), time_buffer,
+          (int)(now.tv_nsec), gettid(), display_file, args->line,
+          args->message);
 }
 
 #endif

src/core/support/log_posix.c

@@ -47,17 +47,40 @@
 
 static long gettid() { return pthread_self(); }
 
-void gpr_vlog(const char *file, int line, gpr_log_severity severity,
-              const char *format, va_list args) {
+void gpr_log(const char *file, int line, gpr_log_severity severity,
+             const char *format, ...) {
+  char buf[64];
+  char *allocated = NULL;
+  char *message = NULL;
+  int ret;
+  va_list args;
+  va_start(args, format);
+  ret = vsnprintf(buf, format, args);
+  va_end(args);
+  if (ret < 0) {
+    message = NULL;
+  } else if (ret <= sizeof(buf) - 1) {
+    message = buf;
+  } else {
+    message = allocated = gpr_malloc(ret + 1);
+    va_start(args, format);
+    vsnprintf(message, format, args);
+    va_end(args);
+  }
+  gpr_log_message(file, line, severity, message);
+  gpr_free(allocated);
+}
+
+void gpr_default_log(gpr_log_func_args *args) {
   char *final_slash;
   const char *display_file;
   char time_buffer[64];
   gpr_timespec now = gpr_now();
   struct tm tm;
 
-  final_slash = strrchr(file, '/');
+  final_slash = strrchr(args->file, '/');
   if (final_slash == NULL)
-    display_file = file;
+    display_file = args->file;
   else
     display_file = final_slash + 1;
 
@@ -68,12 +91,10 @@ void gpr_vlog(const char *file, int line, gpr_log_severity severity,
     strcpy(time_buffer, "error:strftime");
   }
 
-  flockfile(stderr);
-  fprintf(stderr, "%s%s.%09d %7ld %s:%d] ", gpr_log_severity_string(severity),
-          time_buffer, (int)(now.tv_nsec), gettid(), display_file, line);
-  vfprintf(stderr, format, args);
-  fputc('\n', stderr);
-  funlockfile(stderr);
+  fprintf(stderr, "%s%s.%09d %7ld %s:%d] %s\n",
+          gpr_log_severity_string(args->severity), time_buffer,
+          (int)(now.tv_nsec), gettid(), display_file, args->line,
+          args->message);
 }
 
 #endif /* defined(GPR_POSIX_LOG) */

src/core/support/log_win32.c

@@ -39,12 +39,42 @@
 #include <stdio.h>
 #include <stdarg.h>
 
+void gpr_log(const char *file, int line, gpr_log_severity severity,
+             const char *message) {
+  const char *message = NULL;
+  va_list args;
+  int ret;
+
+  /* Determine the length. */
+  va_start(args, format);
+  ret = _vscprintf(format, args);
+  va_end(args);
+  if (!(0 <= ret && ret < ~(size_t)0)) {
+    message = NULL;
+  } else {
+    /* Allocate a new buffer, with space for the NUL terminator. */
+    strp_buflen = (size_t)ret + 1;
+    message = gpr_malloc(strp_buflen);
+
+    /* Print to the buffer. */
+    va_start(args, format);
+    ret = vsnprintf_s(message, strp_buflen, _TRUNCATE, format, args);
+    va_end(args);
+    if (ret != strp_buflen - 1) {
+      /* This should never happen. */
+      gpr_free(message);
+      message = NULL;
+    }
+  }
+
+  gpr_log_message(file, line, severity, message);
+  gpr_free(message);
+}
+
 /* Simple starter implementation */
-void gpr_vlog(const char *file, int line, gpr_log_severity severity,
-              const char *format, va_list args) {
-  fprintf(stderr, "%s %s:%d: ", gpr_log_severity_string(severity), file, line);
-  vfprintf(stderr, format, args);
-  fputc('\n', stderr);
+void gpr_default_log(gpr_log_func_args *args) {
+  fprintf(stderr, "%s %s:%d: %s\n", gpr_log_severity_string(severity),
+          args->file, args->line, args->message);
 }
 
 #endif

test/core/support/log_test.c

@@ -32,8 +32,17 @@
  */
 
 #include <grpc/support/log.h>
+
+#include <string.h>
+
 #include "test/core/util/test_config.h"
 
+static void test_callback(gpr_log_func_args *args) {
+  GPR_ASSERT(0 == strcmp(__FILE__, args->file));
+  GPR_ASSERT(args->severity == GPR_LOG_SEVERITY_INFO);
+  GPR_ASSERT(0 == strcmp(args->message, "hello 1 2 3"));
+}
+
 int main(int argc, char **argv) {
   grpc_test_init(argc, argv);
   /* test logging at various verbosity levels */
@@ -42,6 +51,9 @@ int main(int argc, char **argv) {
   gpr_log(GPR_ERROR, "%s", "hello world");
   /* should succeed */
   GPR_ASSERT(1);
+  gpr_set_log_function(test_callback);
+  gpr_log_message(GPR_INFO, "hello 1 2 3");
+  gpr_log(GPR_INFO, "hello %d %d %d", 1, 2, 3);
   /* TODO(ctiller): should we add a GPR_ASSERT failure test here */
   return 0;
 }