Merge PR #1326 'Add verification of log macros'

6 files changed, 119 insertions, 10 deletions

diff --git a/.ci/common.sh b/.ci/common.sh
index d84a306885..76faf595c8 100644
--- a/.ci/common.sh
+++ b/.ci/common.sh
@@ -67,3 +67,5 @@ install_prebuilt_deps
 sudo apt-mark hold oracle-java7-installer oracle-java8-installer
 
 sudo apt-get update
+
+export CFLAGS='-DMIN_LOG_LEVEL=0'  # force verification of DLOG macros
diff --git a/scripts/msgpack-gen.lua b/scripts/msgpack-gen.lua
index ba962d69d1..284956a43c 100644
--- a/scripts/msgpack-gen.lua
+++ b/scripts/msgpack-gen.lua
@@ -86,6 +86,7 @@ end
 output = io.open(outputf, 'wb')
 
 output:write([[
+#include <inttypes.h>
 #include <stdbool.h>
 #include <stdint.h>
 #include <assert.h>
@@ -163,7 +164,13 @@ for i = 1, #functions do
 
   output:write('static Object handle_'..fn.name..'(uint64_t channel_id, uint64_t request_id, Array args, Error *error)')
   output:write('\n{')
-  output:write('\n  DLOG("Handling msgpack-rpc call to '..fn.name..'(request id: %" PRIu64 ")", request_id);')
+  output:write('\n')
+  output:write('\n#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL\n  {')
+  output:write('\n    char *args_repr = api_stringify(ARRAY_OBJ(args));')
+  output:write('\n    DLOG("msgpack-rpc request received(id: %" PRIu64 ", method: '..fn.name..' , arguments: %s)", request_id, args_repr);')
+  output:write('\n    free(args_repr);')
+  output:write('\n  }\n#endif')
+  output:write('\n')
   output:write('\n  Object ret = NIL;')
   -- Declare/initialize variables that will hold converted arguments
   for j = 1, #fn.parameters do
@@ -228,6 +235,7 @@ for i = 1, #functions do
     end
     -- and check for the error
     output:write('\n  if (error->set) {')
+    output:write('\n    DLOG("msgpack-rpc request failed(id: %" PRIu64 ", method: '..fn.name..' , error: %s)", request_id, error->msg);')
     output:write('\n    goto cleanup;')
     output:write('\n  }\n')
   else
@@ -237,6 +245,11 @@ for i = 1, #functions do
   if fn.return_type ~= 'void' then
     output:write('\n  ret = '..string.upper(real_type(fn.return_type))..'_OBJ(rv);')
   end
+  output:write('\n#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL\n  {')
+  output:write('\n    char *rv_repr = api_stringify(ret);')
+  output:write('\n    DLOG("msgpack-rpc request succeeded(id: %" PRIu64 ", method: '..fn.name..' , return value: %s)", request_id, rv_repr);')
+  output:write('\n    free(rv_repr);')
+  output:write('\n  }\n#endif')
   -- Now generate the cleanup label for freeing memory allocated for the
   -- arguments
   output:write('\n\ncleanup:');
diff --git a/src/nvim/api/private/helpers.c b/src/nvim/api/private/helpers.c
index 093cb0e55f..784915cd16 100644
--- a/src/nvim/api/private/helpers.c
+++ b/src/nvim/api/private/helpers.c
@@ -1,4 +1,5 @@
 #include <assert.h>
+#include <inttypes.h>
 #include <stdbool.h>
 #include <stdlib.h>
 #include <string.h>
@@ -553,6 +554,103 @@ Dictionary api_metadata(void)
   return copy_object(DICTIONARY_OBJ(metadata)).data.dictionary;
 }
 
+char *api_stringify(Object obj)
+{
+  Array array = ARRAY_DICT_INIT;
+  print_to_array(obj, &array);
+  size_t size = 0;
+  for (size_t i = 0; i < array.size; i++) {
+    size += array.items[i].data.string.size;
+  }
+
+  char *rv = xmalloc(size + 1);
+  size_t pos = 0;
+  for (size_t i = 0; i < array.size; i++) {
+    String str = array.items[i].data.string;
+    memcpy(rv + pos, str.data, str.size);
+    pos += str.size;
+    free(str.data);
+  }
+  rv[pos] = NUL;
+  free(array.items);
+  return rv;
+}
+
+static void print_to_array(Object obj, Array *array)
+{
+  char buf[32];
+
+  switch (obj.type) {
+    case kObjectTypeNil:
+      ADD(*array, STRING_OBJ(cstr_to_string("nil")));
+      break;
+
+    case kObjectTypeBoolean:
+      ADD(*array,
+          STRING_OBJ(cstr_to_string(obj.data.boolean ? "true" : "false")));
+      break;
+
+    case kObjectTypeInteger:
+      snprintf(buf, sizeof(buf), "%" PRId64, obj.data.integer);
+      ADD(*array, STRING_OBJ(cstr_to_string(buf)));
+      break;
+
+    case kObjectTypeFloat:
+      snprintf(buf, sizeof(buf), "%f", obj.data.floating);
+      ADD(*array, STRING_OBJ(cstr_to_string(buf)));
+      break;
+
+    case kObjectTypeBuffer:
+      snprintf(buf, sizeof(buf), "Buffer(%" PRIu64 ")", obj.data.buffer);
+      ADD(*array, STRING_OBJ(cstr_to_string(buf)));
+      break;
+
+    case kObjectTypeWindow:
+      snprintf(buf, sizeof(buf), "Window(%" PRIu64 ")", obj.data.window);
+      ADD(*array, STRING_OBJ(cstr_to_string(buf)));
+      break;
+
+    case kObjectTypeTabpage:
+      snprintf(buf, sizeof(buf), "Tabpage(%" PRIu64 ")", obj.data.tabpage);
+      ADD(*array, STRING_OBJ(cstr_to_string(buf)));
+      break;
+
+    case kObjectTypeString:
+      ADD(*array, STRING_OBJ(cstr_to_string("\"")));
+      ADD(*array, STRING_OBJ(cstr_to_string(obj.data.string.data)));
+      ADD(*array, STRING_OBJ(cstr_to_string("\"")));
+      break;
+
+    case kObjectTypeArray:
+      ADD(*array, STRING_OBJ(cstr_to_string("[")));
+      for (size_t i = 0; i < obj.data.array.size; i++) {
+        print_to_array(obj.data.array.items[i], array);
+        if (i < obj.data.array.size - 1) {
+          ADD(*array, STRING_OBJ(cstr_to_string(", ")));
+        }
+      }
+      ADD(*array, STRING_OBJ(cstr_to_string("]")));
+      break;
+
+    case kObjectTypeDictionary:
+      ADD(*array, STRING_OBJ(cstr_to_string("{")));
+      for (size_t i = 0; i < obj.data.dictionary.size; i++) {
+        ADD(*array,
+            STRING_OBJ(cstr_to_string(obj.data.dictionary.items[i].key.data)));
+        ADD(*array, STRING_OBJ(cstr_to_string(": ")));
+        print_to_array(obj.data.dictionary.items[i].value, array);
+        if (i < obj.data.array.size - 1) {
+          ADD(*array, STRING_OBJ(cstr_to_string(", ")));
+        }
+      }
+      ADD(*array, STRING_OBJ(cstr_to_string("}")));
+      break;
+
+    default:
+      ADD(*array, STRING_OBJ(cstr_to_string("INVALID")));
+  }
+}
+
 static void init_error_type_metadata(Dictionary *metadata)
 {
   Dictionary types = ARRAY_DICT_INIT;
diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c
index a1ab12f7c3..94605c37e9 100644
--- a/src/nvim/msgpack_rpc/channel.c
+++ b/src/nvim/msgpack_rpc/channel.c
@@ -461,15 +461,10 @@ static void call_request_handler(Channel *channel,
   msgpack_packer_init(&response, &out_buffer, msgpack_sbuffer_write);
 
   if (error.set) {
-    ELOG("Error dispatching msgpack-rpc call: %s(request: id %" PRIu64 ")",
-         error.msg,
-         request_id);
     channel_write(channel,
                   serialize_response(request_id, &error, NIL, &out_buffer));
   }
 
-  DLOG("Successfully completed mspgack-rpc call(request id: %" PRIu64 ")",
-       request_id);
   channel_write(channel,
                 serialize_response(request_id, &error, result, &out_buffer));
 }
diff --git a/src/nvim/os/input.c b/src/nvim/os/input.c
index b7eba47d5e..2c8026d099 100644
--- a/src/nvim/os/input.c
+++ b/src/nvim/os/input.c
@@ -264,15 +264,15 @@ static void convert_input(void)
 
   for (int i = (int)count - 1; i >= 0; i--) {
     if (inbuf[i] == 3) {
+      got_int = true;
       consume_count = (size_t)i;
       break;
     }
   }
 
-  if (consume_count) {
+  if (got_int) {
     // Remove everything typed before the CTRL-C
     rbuffer_consumed(input_buffer, consume_count);
-    got_int = true;
   }
 }
 
diff --git a/src/nvim/os/rstream.c b/src/nvim/os/rstream.c
index 8cfd9d1b75..d96b3d931c 100644
--- a/src/nvim/os/rstream.c
+++ b/src/nvim/os/rstream.c
@@ -73,13 +73,14 @@ void rbuffer_consumed(RBuffer *rbuffer, size_t count)
 void rbuffer_produced(RBuffer *rbuffer, size_t count)
 {
   rbuffer->wpos += count;
-  DLOG("Received %u bytes from RStream(%p)", (size_t)cnt, rbuffer->rstream);
+  DLOG("Received %u bytes from RStream(%p)", (size_t)count, rbuffer->rstream);
 
   rbuffer_relocate(rbuffer);
   if (rbuffer->rstream && rbuffer->wpos == rbuffer->capacity) {
     // The last read filled the buffer, stop reading for now
+    //
     rstream_stop(rbuffer->rstream);
-    DLOG("Buffer for RStream(%p) is full, stopping it", rstream);
+    DLOG("Buffer for RStream(%p) is full, stopping it", rbuffer->rstream);
   }
 }