Merge pull request #6875 from y-zeng/log_check

Add format check for gpr_log and gpr_asprintf, add gpr_strpad 

14 files changed, 68 insertions, 37 deletions

diff --git a/src/core/ext/lb_policy/round_robin/round_robin.c b/src/core/ext/lb_policy/round_robin/round_robin.c
index da2cdfe8e9..40dd7c5940 100644
--- a/src/core/ext/lb_policy/round_robin/round_robin.c
+++ b/src/core/ext/lb_policy/round_robin/round_robin.c
@@ -333,7 +333,7 @@ static void start_picking(grpc_exec_ctx *exec_ctx, round_robin_lb_policy *p) {
   p->started_picking = 1;
 
   if (grpc_lb_round_robin_trace) {
-    gpr_log(GPR_DEBUG, "LB_POLICY: p=%p num_subchannels=%d", p,
+    gpr_log(GPR_DEBUG, "LB_POLICY: p=%p num_subchannels=%" PRIuPTR, p,
             p->num_subchannels);
   }
 
diff --git a/src/core/ext/resolver/dns/native/dns_resolver.c b/src/core/ext/resolver/dns/native/dns_resolver.c
index 620ba4e2aa..5efc95e0fa 100644
--- a/src/core/ext/resolver/dns/native/dns_resolver.c
+++ b/src/core/ext/resolver/dns/native/dns_resolver.c
@@ -183,7 +183,8 @@ static void dns_on_resolved(grpc_exec_ctx *exec_ctx, void *arg,
     gpr_timespec now = gpr_now(GPR_CLOCK_MONOTONIC);
     gpr_timespec next_try = gpr_backoff_step(&r->backoff_state, now);
     gpr_timespec timeout = gpr_time_sub(next_try, now);
-    gpr_log(GPR_DEBUG, "dns resolution failed: retrying in %d.%09d seconds",
+    gpr_log(GPR_DEBUG,
+            "dns resolution failed: retrying in %" PRId64 ".%09d seconds",
             timeout.tv_sec, timeout.tv_nsec);
     GPR_ASSERT(!r->have_retry_timer);
     r->have_retry_timer = true;
diff --git a/src/core/ext/transport/chttp2/server/insecure/server_chttp2.c b/src/core/ext/transport/chttp2/server/insecure/server_chttp2.c
index 0428bb1e3d..c95dd20d1d 100644
--- a/src/core/ext/transport/chttp2/server/insecure/server_chttp2.c
+++ b/src/core/ext/transport/chttp2/server/insecure/server_chttp2.c
@@ -111,13 +111,14 @@ int grpc_server_add_insecure_http2_port(grpc_server *server, const char *addr) {
     }
   }
   if (count == 0) {
-    gpr_log(GPR_ERROR, "No address added out of total %d resolved",
+    gpr_log(GPR_ERROR, "No address added out of total %" PRIuPTR " resolved",
             resolved->naddrs);
     goto error;
   }
   if (count != resolved->naddrs) {
-    gpr_log(GPR_ERROR, "Only %d addresses added out of total %d resolved",
-            count, resolved->naddrs);
+    gpr_log(GPR_ERROR,
+            "Only %d addresses added out of total %" PRIuPTR " resolved", count,
+            resolved->naddrs);
   }
   grpc_resolved_addresses_destroy(resolved);
 
diff --git a/src/core/ext/transport/chttp2/server/secure/server_secure_chttp2.c b/src/core/ext/transport/chttp2/server/secure/server_secure_chttp2.c
index ebbefbcd89..e3437e5ed3 100644
--- a/src/core/ext/transport/chttp2/server/secure/server_secure_chttp2.c
+++ b/src/core/ext/transport/chttp2/server/secure/server_secure_chttp2.c
@@ -229,13 +229,14 @@ int grpc_server_add_secure_http2_port(grpc_server *server, const char *addr,
     }
   }
   if (count == 0) {
-    gpr_log(GPR_ERROR, "No address added out of total %d resolved",
+    gpr_log(GPR_ERROR, "No address added out of total %" PRIuPTR " resolved",
             resolved->naddrs);
     goto error;
   }
   if (count != resolved->naddrs) {
-    gpr_log(GPR_ERROR, "Only %d addresses added out of total %d resolved",
-            count, resolved->naddrs);
+    gpr_log(GPR_ERROR,
+            "Only %d addresses added out of total %" PRIuPTR " resolved", count,
+            resolved->naddrs);
     /* if it's an error, don't we want to goto error; here ? */
   }
   grpc_resolved_addresses_destroy(resolved);
diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.c b/src/core/ext/transport/chttp2/transport/chttp2_transport.c
index 2375a4587f..6e8640f1b3 100644
--- a/src/core/ext/transport/chttp2/transport/chttp2_transport.c
+++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.c
@@ -964,7 +964,7 @@ static void perform_stream_op_locked(grpc_exec_ctx *exec_ctx,
     if (metadata_size > metadata_peer_limit) {
       gpr_log(GPR_DEBUG,
               "to-be-sent initial metadata size exceeds peer limit "
-              "(%lu vs. %lu)",
+              "(%" PRIuPTR " vs. %" PRIuPTR ")",
               metadata_size, metadata_peer_limit);
       cancel_from_api(exec_ctx, transport_global, stream_global,
                       GRPC_STATUS_RESOURCE_EXHAUSTED, NULL);
@@ -1019,7 +1019,7 @@ static void perform_stream_op_locked(grpc_exec_ctx *exec_ctx,
     if (metadata_size > metadata_peer_limit) {
       gpr_log(GPR_DEBUG,
               "to-be-sent trailing metadata size exceeds peer limit "
-              "(%lu vs. %lu)",
+              "(%" PRIuPTR " vs. %" PRIuPTR ")",
               metadata_size, metadata_peer_limit);
       cancel_from_api(exec_ctx, transport_global, stream_global,
                       GRPC_STATUS_RESOURCE_EXHAUSTED, NULL);
@@ -2019,10 +2019,13 @@ static char *format_flowctl_context_var(const char *context, const char *var,
                                         int64_t val, uint32_t id,
                                         char **scope) {
   char *underscore_pos;
+  char *buf;
   char *result;
   if (context == NULL) {
     *scope = NULL;
-    gpr_asprintf(&result, "%s(%lld)", var, val);
+    gpr_asprintf(&buf, "%s(%" PRId64 ")", var, val);
+    result = gpr_leftpad(buf, ' ', 40);
+    gpr_free(buf);
     return result;
   }
   underscore_pos = strchr(context, '_');
@@ -2033,7 +2036,9 @@ static char *format_flowctl_context_var(const char *context, const char *var,
     gpr_asprintf(scope, "%s[%d]", tmp, id);
     gpr_free(tmp);
   }
-  gpr_asprintf(&result, "%s.%s(%lld)", underscore_pos + 1, var, val);
+  gpr_asprintf(&buf, "%s.%s(%" PRId64 ")", underscore_pos + 1, var, val);
+  result = gpr_leftpad(buf, ' ', 40);
+  gpr_free(buf);
   return result;
 }
 
@@ -2054,6 +2059,8 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase,
                                uint32_t stream_id, int64_t val1, int64_t val2) {
   char *scope1;
   char *scope2;
+  char *tmp_phase;
+  char *tmp_scope1;
   char *label1 =
       format_flowctl_context_var(context1, var1, val1, stream_id, &scope1);
   char *label2 =
@@ -2061,14 +2068,18 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase,
   char *clisvr = is_client ? "client" : "server";
   char *prefix;
 
-  gpr_asprintf(&prefix, "FLOW % 8s: %s % 11s ", phase, clisvr, scope1);
+  tmp_phase = gpr_leftpad(phase, ' ', 8);
+  tmp_scope1 = gpr_leftpad(scope1, ' ', 11);
+  gpr_asprintf(&prefix, "FLOW %s: %s %s ", phase, clisvr, scope1);
+  gpr_free(tmp_phase);
+  gpr_free(tmp_scope1);
 
   switch (op) {
     case GRPC_CHTTP2_FLOWCTL_MOVE:
       GPR_ASSERT(samestr(scope1, scope2));
       if (val2 != 0) {
         gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
-                "%sMOVE   % 40s <- % 40s giving %d", prefix, label1, label2,
+                "%sMOVE   %s <- %s giving %" PRId64, prefix, label1, label2,
                 val1 + val2);
       }
       break;
@@ -2076,7 +2087,7 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase,
       GPR_ASSERT(val2 >= 0);
       if (val2 != 0) {
         gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
-                "%sCREDIT % 40s by % 40s giving %d", prefix, label1, label2,
+                "%sCREDIT %s by %s giving %" PRId64, prefix, label1, label2,
                 val1 + val2);
       }
       break;
@@ -2084,7 +2095,7 @@ void grpc_chttp2_flowctl_trace(const char *file, int line, const char *phase,
       GPR_ASSERT(val2 >= 0);
       if (val2 != 0) {
         gpr_log(file, line, GPR_LOG_SEVERITY_DEBUG,
-                "%sDEBIT  % 40s by % 40s giving %d", prefix, label1, label2,
+                "%sDEBIT  %s by %s giving %" PRId64, prefix, label1, label2,
                 val1 - val2);
       }
       break;
diff --git a/src/core/ext/transport/chttp2/transport/parsing.c b/src/core/ext/transport/chttp2/transport/parsing.c
index 4bd374b7fa..3c74258352 100644
--- a/src/core/ext/transport/chttp2/transport/parsing.c
+++ b/src/core/ext/transport/chttp2/transport/parsing.c
@@ -534,14 +534,14 @@ static grpc_chttp2_parse_error update_incoming_window(
     grpc_chttp2_stream_parsing *stream_parsing) {
   uint32_t incoming_frame_size = transport_parsing->incoming_frame_size;
   if (incoming_frame_size > transport_parsing->incoming_window) {
-    gpr_log(GPR_ERROR, "frame of size %d overflows incoming window of %d",
+    gpr_log(GPR_ERROR, "frame of size %d overflows incoming window of %" PRId64,
             transport_parsing->incoming_frame_size,
             transport_parsing->incoming_window);
     return GRPC_CHTTP2_CONNECTION_ERROR;
   }
 
   if (incoming_frame_size > stream_parsing->incoming_window) {
-    gpr_log(GPR_ERROR, "frame of size %d overflows incoming window of %d",
+    gpr_log(GPR_ERROR, "frame of size %d overflows incoming window of %" PRId64,
             transport_parsing->incoming_frame_size,
             stream_parsing->incoming_window);
     return GRPC_CHTTP2_CONNECTION_ERROR;
@@ -649,7 +649,8 @@ static void on_initial_header(void *tp, grpc_mdelem *md) {
     if (new_size > metadata_size_limit) {
       if (!stream_parsing->exceeded_metadata_size) {
         gpr_log(GPR_DEBUG,
-                "received initial metadata size exceeds limit (%lu vs. %lu)",
+                "received initial metadata size exceeds limit (%" PRIuPTR
+                " vs. %" PRIuPTR ")",
                 new_size, metadata_size_limit);
         stream_parsing->seen_error = true;
         stream_parsing->exceeded_metadata_size = true;
@@ -695,7 +696,8 @@ static void on_trailing_header(void *tp, grpc_mdelem *md) {
   if (new_size > metadata_size_limit) {
     if (!stream_parsing->exceeded_metadata_size) {
       gpr_log(GPR_DEBUG,
-              "received trailing metadata size exceeds limit (%lu vs. %lu)",
+              "received trailing metadata size exceeds limit (%" PRIuPTR
+              " vs. %" PRIuPTR ")",
               new_size, metadata_size_limit);
       stream_parsing->seen_error = true;
       stream_parsing->exceeded_metadata_size = true;
diff --git a/src/core/lib/channel/compress_filter.c b/src/core/lib/channel/compress_filter.c
index 4fe9a7f045..32f4f8d37e 100644
--- a/src/core/lib/channel/compress_filter.c
+++ b/src/core/lib/channel/compress_filter.c
@@ -177,8 +177,8 @@ static void finish_send_message(grpc_exec_ctx *exec_ctx,
       const float savings_ratio = 1.0f - (float)after_size / (float)before_size;
       GPR_ASSERT(grpc_compression_algorithm_name(calld->compression_algorithm,
                                                  &algo_name));
-      gpr_log(GPR_DEBUG,
-              "Compressed[%s] %d bytes vs. %d bytes (%.2f%% savings)",
+      gpr_log(GPR_DEBUG, "Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR
+                         " bytes (%.2f%% savings)",
               algo_name, before_size, after_size, 100 * savings_ratio);
     }
     gpr_slice_buffer_swap(&calld->slices, &tmp);
@@ -188,10 +188,10 @@ static void finish_send_message(grpc_exec_ctx *exec_ctx,
       char *algo_name;
       GPR_ASSERT(grpc_compression_algorithm_name(calld->compression_algorithm,
                                                  &algo_name));
-      gpr_log(
-          GPR_DEBUG,
-          "Algorithm '%s' enabled but decided not to compress. Input size: %d",
-          algo_name, calld->slices.length);
+      gpr_log(GPR_DEBUG,
+              "Algorithm '%s' enabled but decided not to compress. Input size: "
+              "%" PRIuPTR,
+              algo_name, calld->slices.length);
     }
   }
 
diff --git a/src/core/lib/iomgr/iomgr.c b/src/core/lib/iomgr/iomgr.c
index 60cef8ba77..89292a153e 100644
--- a/src/core/lib/iomgr/iomgr.c
+++ b/src/core/lib/iomgr/iomgr.c
@@ -96,7 +96,8 @@ void grpc_iomgr_shutdown(void) {
             gpr_time_sub(gpr_now(GPR_CLOCK_REALTIME), last_warning_time),
             gpr_time_from_seconds(1, GPR_TIMESPAN)) >= 0) {
       if (g_root_object.next != &g_root_object) {
-        gpr_log(GPR_DEBUG, "Waiting for %d iomgr objects to be destroyed",
+        gpr_log(GPR_DEBUG,
+                "Waiting for %" PRIuPTR " iomgr objects to be destroyed",
                 count_objects());
       }
       last_warning_time = gpr_now(GPR_CLOCK_REALTIME);
@@ -114,9 +115,9 @@ void grpc_iomgr_shutdown(void) {
       if (gpr_cv_wait(&g_rcv, &g_mu, short_deadline)) {
         if (gpr_time_cmp(gpr_now(GPR_CLOCK_REALTIME), shutdown_deadline) > 0) {
           if (g_root_object.next != &g_root_object) {
-            gpr_log(GPR_DEBUG,
-                    "Failed to free %d iomgr objects before shutdown deadline: "
-                    "memory leaks are likely",
+            gpr_log(GPR_DEBUG, "Failed to free %" PRIuPTR
+                               " iomgr objects before shutdown deadline: "
+                               "memory leaks are likely",
                     count_objects());
             dump_objects("LEAKED");
             if (grpc_iomgr_abort_on_leaks()) {
diff --git a/src/core/lib/support/log_linux.c b/src/core/lib/support/log_linux.c
index ca04c022e3..508fae4eec 100644
--- a/src/core/lib/support/log_linux.c
+++ b/src/core/lib/support/log_linux.c
@@ -95,9 +95,9 @@ void gpr_default_log(gpr_log_func_args *args) {
     strcpy(time_buffer, "error:strftime");
   }
 
-  gpr_asprintf(&prefix, "%s%s.%09d %7tu %s:%d]",
+  gpr_asprintf(&prefix, "%s%s.%09" PRId32 " %7ld %s:%d]",
                gpr_log_severity_string(args->severity), time_buffer,
-               (int)(now.tv_nsec), gettid(), display_file, args->line);
+               now.tv_nsec, gettid(), display_file, args->line);
 
   fprintf(stderr, "%-60s %s\n", prefix, args->message);
   gpr_free(prefix);
diff --git a/src/core/lib/support/string.c b/src/core/lib/support/string.c
index a2ab6c5f1f..30c1e67647 100644
--- a/src/core/lib/support/string.c
+++ b/src/core/lib/support/string.c
@@ -194,6 +194,16 @@ int int64_ttoa(int64_t value, char *string) {
   return i;
 }
 
+char *gpr_leftpad(const char *str, char flag, size_t length) {
+  const size_t str_length = strlen(str);
+  const size_t out_length = str_length > length ? str_length : length;
+  char *out = gpr_malloc(out_length + 1);
+  memset(out, flag, out_length - str_length);
+  memcpy(out + out_length - str_length, str, str_length);
+  out[out_length] = 0;
+  return out;
+}
+
 char *gpr_strjoin(const char **strs, size_t nstrs, size_t *final_length) {
   return gpr_strjoin_sep(strs, nstrs, "", final_length);
 }
diff --git a/src/core/lib/support/string.h b/src/core/lib/support/string.h
index ea58610914..2b6bb3eec6 100644
--- a/src/core/lib/support/string.h
+++ b/src/core/lib/support/string.h
@@ -83,6 +83,10 @@ int int64_ttoa(int64_t value, char *output);
 /* Reverse a run of bytes */
 void gpr_reverse_bytes(char *str, int len);
 
+/* Pad a string with flag characters. The given length specifies the minimum
+   field width. The input string is never truncated. */
+char *gpr_leftpad(const char *str, char flag, size_t length);
+
 /* Join a set of strings, returning the resulting string.
    Total combined length (excluding null terminator) is returned in total_length
    if it is non-null. */
diff --git a/src/core/lib/surface/call.c b/src/core/lib/surface/call.c
index a9b1e25a77..c613f325dc 100644
--- a/src/core/lib/surface/call.c
+++ b/src/core/lib/surface/call.c
@@ -1182,7 +1182,7 @@ static void validate_filtered_metadata(grpc_exec_ctx *exec_ctx,
     if (algo >= GRPC_COMPRESS_ALGORITHMS_COUNT) {
       gpr_asprintf(&error_msg, "Invalid compression algorithm value '%d'.",
                    algo);
-      gpr_log(GPR_ERROR, error_msg);
+      gpr_log(GPR_ERROR, "%s", error_msg);
       close_with_status(exec_ctx, call, GRPC_STATUS_UNIMPLEMENTED, error_msg);
     } else if (grpc_compression_options_is_algorithm_enabled(
                    &compression_options, algo) == 0) {
@@ -1191,7 +1191,7 @@ static void validate_filtered_metadata(grpc_exec_ctx *exec_ctx,
       grpc_compression_algorithm_name(algo, &algo_name);
       gpr_asprintf(&error_msg, "Compression algorithm '%s' is disabled.",
                    algo_name);
-      gpr_log(GPR_ERROR, error_msg);
+      gpr_log(GPR_ERROR, "%s", error_msg);
       close_with_status(exec_ctx, call, GRPC_STATUS_UNIMPLEMENTED, error_msg);
     } else {
       call->incoming_compression_algorithm = algo;
diff --git a/src/core/lib/surface/call_log_batch.c b/src/core/lib/surface/call_log_batch.c
index a6d1d5149f..31c074f15d 100644
--- a/src/core/lib/surface/call_log_batch.c
+++ b/src/core/lib/surface/call_log_batch.c
@@ -112,7 +112,7 @@ void grpc_call_log_batch(char *file, int line, gpr_log_severity severity,
   size_t i;
   for (i = 0; i < nops; i++) {
     tmp = grpc_op_string(&ops[i]);
-    gpr_log(file, line, severity, "ops[%d]: %s", i, tmp);
+    gpr_log(file, line, severity, "ops[%" PRIuPTR "]: %s", i, tmp);
     gpr_free(tmp);
   }
 }
diff --git a/src/core/lib/transport/metadata.c b/src/core/lib/transport/metadata.c
index 79de54beb5..0677f29766 100644
--- a/src/core/lib/transport/metadata.c
+++ b/src/core/lib/transport/metadata.c
@@ -235,7 +235,7 @@ void grpc_mdctx_global_shutdown(void) {
     gc_mdtab(shard);
     /* TODO(ctiller): GPR_ASSERT(shard->count == 0); */
     if (shard->count != 0) {
-      gpr_log(GPR_DEBUG, "WARNING: %d metadata elements were leaked",
+      gpr_log(GPR_DEBUG, "WARNING: %" PRIuPTR " metadata elements were leaked",
               shard->count);
       if (grpc_iomgr_abort_on_leaks()) {
         abort();
@@ -248,7 +248,7 @@ void grpc_mdctx_global_shutdown(void) {
     gpr_mu_destroy(&shard->mu);
     /* TODO(ctiller): GPR_ASSERT(shard->count == 0); */
     if (shard->count != 0) {
-      gpr_log(GPR_DEBUG, "WARNING: %d metadata strings were leaked",
+      gpr_log(GPR_DEBUG, "WARNING: %" PRIuPTR " metadata strings were leaked",
               shard->count);
       for (size_t j = 0; j < shard->capacity; j++) {
         for (internal_string *s = shard->strs[j]; s; s = s->bucket_next) {