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)

5 files changed, 25 insertions, 10 deletions

diff --git a/src/nvim/log.h b/src/nvim/log.h
index 6d97304af4..f1ee63a4e2 100644
--- a/src/nvim/log.h
+++ b/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
diff --git a/src/nvim/os/channel.c b/src/nvim/os/channel.c
index c12779e794..11a58f246a 100644
--- a/src/nvim/os/channel.c
+++ b/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);
diff --git a/src/nvim/os/event.c b/src/nvim/os/event.c
index 0528339865..6367a60af7 100644
--- a/src/nvim/os/event.c
+++ b/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
diff --git a/src/nvim/os/msgpack_rpc.c b/src/nvim/os/msgpack_rpc.c
index 402e741370..c03d8dccca 100644
--- a/src/nvim/os/msgpack_rpc.c
+++ b/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);
 }
 
diff --git a/src/nvim/os/rstream.c b/src/nvim/os/rstream.c
index 5286599586..96dd26407a 100644
--- a/src/nvim/os/rstream.c
+++ b/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;