debug: Improve debugging of msgpack-rpc requests

- Add the api_stringify function to display API objects
- Use api_stringify to display request arguments and return values in DLOG
  statements.

scripts/msgpack-gen.lua

@@ -164,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
@@ -229,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
@@ -238,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:');

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;

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