api/events/msgpack: Insert log statements to improve debugging

Also changed the default log level to INFO so developers won't end up with big
log files without asking explicitly(DLOG statements were placed in really "hot"
code)

scripts/msgpack-gen.lua

@@ -91,6 +91,7 @@ output:write([[
 #include <assert.h>
 #include <msgpack.h>
 
+#include "nvim/log.h"
 #include "nvim/os/msgpack_rpc.h"
 #include "nvim/os/msgpack_rpc_helpers.h"
 #include "nvim/api/private/helpers.h"
@@ -133,6 +134,7 @@ for i = 1, #api.functions do
 
   output:write('static Object handle_'..fn.name..'(uint64_t channel_id, msgpack_object *req, Error *error)')
   output:write('\n{')
+  output:write('\n  DLOG("Received msgpack-rpc call to '..fn.name..'(request id: %" PRIu64 ")", req->via.array.ptr[1].via.u64);')
   -- Declare/initialize variables that will hold converted arguments
   for j = 1, #fn.parameters do
     local param = fn.parameters[j]

src/nvim/log.h

@@ -19,9 +19,9 @@
 #endif
 
 // MIN_LOG_LEVEL can be defined during compilation to adjust the desired level
-// of logging. DEBUG_LOG_LEVEL is used by default.
+// of logging. INFO_LOG_LEVEL is used by default.
 #ifndef MIN_LOG_LEVEL
-#  define MIN_LOG_LEVEL DEBUG_LOG_LEVEL
+#  define MIN_LOG_LEVEL INFO_LOG_LEVEL
 #endif
 
 #ifndef DISABLE_LOG

src/nvim/os/channel.c

@@ -305,6 +305,9 @@ static void parse_msgpack(RStream *rstream, void *data, bool eof)
 
   channel->rpc_call_level++;
   uint32_t count = rstream_available(rstream);
+  DLOG("Feeding the msgpack parser with %u bytes of data from RStream(%p)",
+       count,
+       rstream);
 
   // Feed the unpacker with data
   msgpack_unpacker_reserve_buffer(channel->unpacker, count);

src/nvim/os/event.c

@@ -94,16 +94,18 @@ bool event_poll(int32_t ms)
     run_mode = UV_RUN_NOWAIT;
   }
 
-  bool events_processed;
+  size_t processed_events;
 
   do {
     // Run one event loop iteration, blocking for events if run_mode is
     // UV_RUN_ONCE
+    DLOG("Entering event loop");
     uv_run(uv_default_loop(), run_mode);
-    events_processed = event_process(false);
+    processed_events = event_process(false);
+    DLOG("Exited event loop, processed %u events", processed_events);
   } while (
       // Continue running if ...
-      !events_processed &&   // we didn't process any immediate events
+      !processed_events &&   // we didn't process any immediate events
       !event_has_deferred() &&   // no events are waiting to be processed
       run_mode != UV_RUN_NOWAIT &&   // ms != 0
       !timer_data.timed_out);  // we didn't get a timeout
@@ -122,7 +124,7 @@ bool event_poll(int32_t ms)
     event_process(false);
   }
 
-  return !timer_data.timed_out && (events_processed || event_has_deferred());
+  return !timer_data.timed_out && (processed_events || event_has_deferred());
 }
 
 bool event_has_deferred(void)
@@ -137,13 +139,12 @@ void event_push(Event event, bool deferred)
 }
 
 // Runs the appropriate action for each queued event
-bool event_process(bool deferred)
+size_t event_process(bool deferred)
 {
-  bool processed_events = false;
+  size_t count = 0;
   Event event;
 
   while (kl_shift(Event, get_queue(deferred), &event) == 0) {
-    processed_events = true;
     switch (event.type) {
       case kEventSignal:
         signal_handle(event);
@@ -157,9 +158,10 @@ bool event_process(bool deferred)
       default:
         abort();
     }
+    count++;
   }
 
-  return processed_events;
+  return count;
 }
 
 // Set a flag in the `event_poll` loop for signaling of a timeout

src/nvim/os/msgpack_rpc.c

@@ -1,9 +1,11 @@
 #include <stdint.h>
 #include <stdbool.h>
+#include <inttypes.h>
 
 #include <msgpack.h>
 
 #include "nvim/vim.h"
+#include "nvim/log.h"
 #include "nvim/memory.h"
 #include "nvim/os/wstream.h"
 #include "nvim/os/msgpack_rpc.h"
@@ -51,9 +53,14 @@ WBuffer *msgpack_rpc_call(uint64_t channel_id,
   msgpack_packer_init(&response, sbuffer, msgpack_sbuffer_write);
 
   if (error.set) {
+    ELOG("Error dispatching msgpack-rpc call: %s(request: id %" PRIu64 ")",
+         error.msg,
+         response_id);
     return serialize_response(response_id, error.msg, NIL, sbuffer);
   }
 
+  DLOG("Successfully completed mspgack-rpc call(request id: %" PRIu64 ")",
+       response_id);
   return serialize_response(response_id, NULL, rv, sbuffer);
 }
 

src/nvim/os/rstream.c

@@ -260,6 +260,7 @@ static void read_cb(uv_stream_t *stream, ssize_t cnt, const uv_buf_t *buf)
 
   if (cnt <= 0) {
     if (cnt != UV_ENOBUFS) {
+      DLOG("Closing RStream(%p)", rstream);
       // Read error or EOF, either way stop the stream and invoke the callback
       // with eof == true
       uv_read_stop(stream);
@@ -274,10 +275,12 @@ static void read_cb(uv_stream_t *stream, ssize_t cnt, const uv_buf_t *buf)
   // Data was already written, so all we need is to update 'wpos' to reflect
   // the space actually used in the buffer.
   rstream->wpos += nread;
+  DLOG("Received %u bytes from RStream(%p)", (size_t)cnt, rstream);
 
   if (rstream->wpos == rstream->buffer_size) {
     // The last read filled the buffer, stop reading for now
     rstream_stop(rstream);
+    DLOG("Buffer for RStream(%p) is full, stopping it", rstream);
   }
 
   rstream->reading = false;