command: GET_LOG, from a lock-free ring of the last lines logged

RARCH_LOG_V copies each formatted line into a ring of the last 256
lines once it is armed, which the MCP server's start or the first
GET_LOG does; unarmed, a log line costs one relaxed load more. Any
thread may log: a writer claims a line number, writes the slot as
atomic words between a busy mark and its stamp, and the reader keeps a
line only when the stamp matches before and after the copy, so a
reader never waits and never sees a torn line. GET_LOG answers the
lines since the one asked for, then NEXT; lines overwritten before they
were read are counted as SKIPPED. Desktop builds with the MCP server
only; samples/runloop/log_ring writes from four threads while reading,
under ASan and TSan.

.github/workflows/Linux-network-clients.yml

@@ -132,6 +132,17 @@ jobs:
             make -C samples/network/mcp_server check
           make -C samples/network/mcp_server clean
 
+      - name: GET_LOG's ring, written from four threads while read
+        shell: bash
+        working-directory: ${{ github.workspace }}
+        run: |
+          set -eu
+          make -C samples/runloop/log_ring clean
+          make -C samples/runloop/log_ring SANITIZER=address,undefined
+          ASAN_OPTIONS=detect_leaks=1 UBSAN_OPTIONS=halt_on_error=1 \
+            make -C samples/runloop/log_ring check
+          make -C samples/runloop/log_ring clean
+
       - name: Command options and speed setters
         shell: bash
         working-directory: ${{ github.workspace }}

command.c

@@ -2109,6 +2109,51 @@ bool command_set_option(command_t *cmd, const char *arg)
    return true;
 }
 
+#ifdef HAVE_MCP
+/* GET_LOG [since]
+ *
+ * The lines logged since line @since (0 when left out), as many as one
+ * reply holds, then NEXT and the number to ask from next time. Lines
+ * logged before the first GET_LOG, or the MCP server started, are not
+ * kept; SKIPPED and a count says lines were overwritten before they
+ * were read. */
+bool command_get_log(command_t *cmd, const char *arg)
+{
+   size_t first, next, _len;
+   unsigned since = 0;
+   char  *reply;
+
+   while (arg && *arg == ' ')
+      arg++;
+   if (arg && *arg && !command_arg_uint(arg, &since))
+   {
+      command_reply_error(cmd, "GET_LOG", "a line number, not %s", arg);
+      return false;
+   }
+   verbosity_ring_arm();
+   if (!(reply = (char*)malloc(COMMAND_LIST_REPLY_MAX + 1)))
+   {
+      command_reply_error(cmd, "GET_LOG", "out of memory");
+      return false;
+   }
+   /* room kept for the SKIPPED and NEXT lines */
+   _len = verbosity_ring_read(since, reply + 32, COMMAND_LIST_REPLY_MAX - 64,
+         &first, &next);
+   if (first > since)
+   {
+      int n = snprintf(reply, 32, "SKIPPED %u\n", (unsigned)(first - since));
+      memmove(reply + n, reply + 32, _len);
+      _len += (size_t)n;
+   }
+   else
+      memmove(reply, reply + 32, _len);
+   _len += (size_t)snprintf(reply + _len, 32, "NEXT %u\n", (unsigned)next);
+   cmd->replier(cmd, reply, _len);
+   free(reply);
+   return true;
+}
+#endif
+
 /* RUN_FRAMES in progress: frames still to run, and the reply owed */
 static struct
 {

command.h

@@ -541,6 +541,11 @@ struct cmd_action_map
 bool command_get_option(command_t *cmd, const char *arg);
 bool command_set_option(command_t *cmd, const char *arg);
 
+#ifdef HAVE_MCP
+/* GET_LOG [since] */
+bool command_get_log(command_t *cmd, const char *arg);
+#endif
+
 /* RUN_FRAMES <count>; the run loop calls tick after each frame it runs
  * and cancel when the content goes */
 #define COMMAND_RUN_FRAMES_MAX 36000
@@ -632,6 +637,13 @@ static const struct cmd_param cmd_params_option_set[] = {
       CMD_PARAM_STRING, true, NULL, "on|off", NULL },
    { NULL }
 };
+#ifdef HAVE_MCP
+static const struct cmd_param cmd_params_log[] = {
+   { "since", "The first line wanted, as NEXT gave it; 0 when left out.",
+      CMD_PARAM_INT, false, NULL, NULL, "0" },
+   { NULL }
+};
+#endif
 static const struct cmd_param cmd_params_run_frames[] = {
    { "count", "How many frames to run.", CMD_PARAM_INT, true, NULL, NULL,
       NULL },
@@ -730,6 +742,9 @@ static const struct cmd_action_map action_map[] = {
    /* GET_OPTION reports these and more; this stays for the clients that
     * have always asked it. */
    { "GET_CONFIG_PARAM", command_get_config_param, "<param name>", "Report the value of a configuration setting.", CMD_INFO_READ_ONLY | CMD_INFO_NO_TOOL, cmd_params_config },
+#ifdef HAVE_MCP
+   { "GET_LOG",          command_get_log,          "[since]", "Report the lines RetroArch has logged since the given line, then NEXT and the line to ask from next time.", CMD_INFO_READ_ONLY, cmd_params_log },
+#endif
    { "RUN_FRAMES",       command_run_frames,       "<count>", "Pause and run the content the given number of frames, answered once the last has run; it stays paused.", 0, cmd_params_run_frames },
    { "SET_INPUT",        command_set_input,        "<player> <control> <value>", "Hold a RetroPad button or stick axis for the core, over the player's own input, until set again or released. Answers with what the player holds: buttons and axes, tab separated.", 0, cmd_params_input },
    { "RELEASE_INPUT",    command_release_input,    "[player]", "Let go of everything SET_INPUT holds, for one player or all.", 0, cmd_params_input_release },

docs/mcp-server.md

@@ -118,6 +118,13 @@ A hotkey tool that is still a tool answers `<NAME> pressed` for the same
 reason: the press goes out on the next poll, and what it
 changed is read back with `GET_OPTION`.
 
+`GET_LOG [since]` gives the lines RetroArch has logged since line
+`since` (0 when left out), as far as the logging verbosity lets them be
+logged, then `NEXT` and the line number to ask from next time; when
+lines were overwritten before they were read it says `SKIPPED` and how
+many first. The last 256 lines are kept, from when the MCP server
+starts or the first `GET_LOG`.
+
 `RUN_FRAMES <count>` pauses the content, if it is running, and runs it
 that many frames, one per frame advance, answering once the last has
 run; it is left paused. With `SET_INPUT` before it, an assistant plays

network/mcp_server.c

@@ -1388,6 +1388,7 @@ command_t *command_mcp_new(uint16_t port, const char *bind_address,
    cmd->reply_image_to = mcp_reply_image_to;
    cmd->destroy    = mcp_destroy;
    cmd->structured = true;
+   verbosity_ring_arm();
    RARCH_LOG("[MCP] Listening on http://%s:%hu/mcp.\n",
          bind_address, (unsigned short)port);
    return cmd;

samples/network/mcp_server/stubs.c

@@ -20,3 +20,4 @@ void RARCH_ERR(const char *fmt, ...)
    vfprintf(stderr, fmt, ap);
    va_end(ap);
 }
+void verbosity_ring_arm(void) { }

samples/runloop/log_ring/Makefile

@@ -0,0 +1,30 @@
+compiler ?= gcc
+ROOT := ../../..
+LC := $(ROOT)/libretro-common
+TARGET := log_ring_test
+SOURCES := log_ring_test.c $(ROOT)/verbosity.c \
+   $(LC)/rthreads/rthreads.c $(LC)/compat/compat_strl.c \
+   $(LC)/file/file_path.c $(LC)/file/file_path_io.c \
+   $(LC)/streams/file_stream.c $(LC)/vfs/vfs_implementation.c \
+   $(LC)/string/stdstring.c $(LC)/encodings/encoding_utf.c \
+   $(LC)/compat/fopen_utf8.c $(LC)/time/rtime.c $(LC)/string/rstrtod.c
+CFLAGS += -std=gnu89 -Wall -g -O1 -I$(ROOT) -I$(LC)/include -DHAVE_MCP \
+   -DHAVE_THREADS
+LDFLAGS += -lpthread
+ifneq ($(SANITIZER),)
+   CFLAGS += -fsanitize=$(SANITIZER) -fno-omit-frame-pointer
+   LDFLAGS += -fsanitize=$(SANITIZER)
+endif
+ifneq ($(findstring mingw,$(compiler)),)
+   TARGET := $(TARGET).exe
+   LDFLAGS := $(filter-out -lpthread,$(LDFLAGS))
+endif
+
+all: $(TARGET)
+$(TARGET): $(SOURCES) $(ROOT)/verbosity.h
+	$(compiler) $(CFLAGS) $(SOURCES) -o $@ $(LDFLAGS)
+check: $(TARGET)
+	./$(TARGET) 2>/dev/null
+clean:
+	rm -f log_ring_test log_ring_test.exe
+.PHONY: all check clean

samples/runloop/log_ring/log_ring_test.c

@@ -0,0 +1,107 @@
+/* GET_LOG's ring in verbosity.c: lines logged from several threads at
+ * once, read while they are written, arrive whole and in order, and
+ * an overrun is reported as lines skipped rather than torn lines. */
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <rthreads/rthreads.h>
+#include <retro_atomic.h>
+
+#include "../../../verbosity.h"
+
+#define THREADS 4
+#define LINES   20000
+
+static unsigned failures;
+static retro_atomic_int_t done;
+
+#define CHECK(test) do { if (!(test)) { \
+   fprintf(stderr, "FAIL line %u: %s\n", (unsigned)__LINE__, #test); \
+   failures++; } } while (0)
+
+static void writer(void *data)
+{
+   unsigned t = (unsigned)(size_t)data;
+   unsigned i;
+   for (i = 0; i < LINES; i++)
+      RARCH_LOG("w%u %06u ........................................\n", t, i);
+   retro_atomic_fetch_add_int(&done, 1);
+}
+
+/* A line as the writers write it, after the tag RARCH_LOG adds */
+static bool line_whole(const char *s, const char *e)
+{
+   const char *w = strstr(s, "] w");
+   unsigned t, i;
+   if (!w || w > e)
+      return false;
+   if (sscanf(w + 3, "%u %6u", &t, &i) != 2 || t >= THREADS || i >= LINES)
+      return false;
+   return (size_t)(e - w) == strlen("] w0 000000 ") + 40;
+}
+
+static unsigned drain(size_t *since, char *buf, size_t len, unsigned *skipped)
+{
+   size_t first, next;
+   size_t n     = verbosity_ring_read(*since, buf, len, &first, &next);
+   unsigned got = 0;
+   char *s      = buf;
+   CHECK(next >= first && first >= *since);
+   *skipped    += (unsigned)(first - *since);
+   while (s < buf + n)
+   {
+      char *e = strchr(s, '\n');
+      CHECK(e != NULL);
+      if (!e)
+         break;
+      CHECK(line_whole(s, e));
+      got++;
+      s = e + 1;
+   }
+   *since = next;
+   return got;
+}
+
+int main(void)
+{
+   sthread_t *th[THREADS];
+   char      *buf = (char*)malloc(1 << 16);
+   size_t     since = 0, first, next;
+   unsigned   got = 0, skipped = 0, i;
+
+   verbosity_enable();
+   CHECK(verbosity_ring_read(0, buf, 1 << 16, &first, &next) == 0);
+   RARCH_LOG("before the ring is armed\n");
+   CHECK(verbosity_ring_read(0, buf, 1 << 16, &first, &next) == 0);
+   verbosity_ring_arm();
+
+   for (i = 0; i < THREADS; i++)
+      th[i] = sthread_create(writer, (void*)(size_t)i);
+   while (retro_atomic_load_acquire_int(&done) < THREADS)
+      got += drain(&since, buf, 1 << 16, &skipped);
+   for (i = 0; i < THREADS; i++)
+      sthread_join(th[i]);
+   got += drain(&since, buf, 1 << 16, &skipped);
+
+   /* every line was read once or counted as skipped; a slot being
+    * written when read is skipped too, so allow none lost beyond that */
+   CHECK(since == (size_t)THREADS * LINES);
+   CHECK(got + skipped <= (unsigned)(THREADS * LINES));
+   CHECK(got > 0);
+
+   /* a short buffer stops at a whole line, and NEXT resumes there */
+   RARCH_LOG("w0 000001 ........................................\n");
+   RARCH_LOG("w0 000002 ........................................\n");
+   {
+      size_t n = verbosity_ring_read(since, buf, 80, &first, &next);
+      CHECK(n > 0 && n < 80 && next == since + 1);
+      n = verbosity_ring_read(next, buf, 1 << 16, &first, &next);
+      CHECK(n > 0 && next == since + 2);
+   }
+
+   free(buf);
+   printf("log_ring: %s (%u read, %u skipped)\n",
+         failures ? "FAIL" : "PASS", got, skipped);
+   return failures ? 1 : 0;
+}

tools/tsan-samples.list

@@ -83,3 +83,4 @@ samples/ui/companion_thumbs_handoff companion_thumbs_test
 samples/midi/fmsynth_queue fmsynth_queue_test
 samples/input/joypad_slots joypad_slots_test
 samples/audio/rsound_thread rsound_thread_test
+samples/runloop/log_ring log_ring_test

verbosity.c

@@ -354,6 +354,100 @@ static void rarch_log_line_write(FILE *fp, const char *tag_v,
 #endif
 #endif
 
+#ifdef HAVE_MCP
+#include <string.h>
+#include <retro_atomic.h>
+
+/* The last lines logged, for GET_LOG, filled by whatever thread logs
+ * and read on the main thread without a lock: a writer claims a line
+ * number, marks the slot busy, writes the text as atomic words and
+ * stamps the slot with its number; a reader takes a slot's text only
+ * when the stamp is the line it wants before and after the copy. */
+#define LOG_RING_SLOTS  256
+#define LOG_RING_WORDS  (256 / sizeof(size_t))
+
+struct log_ring_slot
+{
+   retro_atomic_size_t stamp; /* line number + 1, 0 while written */
+   retro_atomic_size_t text[LOG_RING_WORDS];
+};
+
+static struct
+{
+   struct log_ring_slot slots[LOG_RING_SLOTS];
+   retro_atomic_size_t  head;
+   retro_atomic_int_t   armed;
+} log_ring;
+
+void verbosity_ring_arm(void)
+{
+   retro_atomic_store_release_int(&log_ring.armed, 1);
+}
+
+static void verbosity_ring_put(const char *line)
+{
+   size_t i;
+   size_t seq;
+   size_t words[LOG_RING_WORDS];
+   struct log_ring_slot *slot;
+
+   if (!retro_atomic_load_relaxed_int(&log_ring.armed))
+      return;
+   memset(words, 0, sizeof(words));
+   strlcpy((char*)words, line, sizeof(words));
+   seq  = retro_atomic_fetch_add_size(&log_ring.head, 1);
+   slot = &log_ring.slots[seq % LOG_RING_SLOTS];
+   retro_atomic_store_relaxed_size(&slot->stamp, 0);
+   retro_atomic_thread_fence_release();
+   for (i = 0; i < LOG_RING_WORDS; i++)
+      retro_atomic_store_relaxed_size(&slot->text[i], words[i]);
+   retro_atomic_store_release_size(&slot->stamp, seq + 1);
+}
+
+size_t verbosity_ring_read(size_t since, char *s, size_t len,
+      size_t *first, size_t *next)
+{
+   size_t _len = 0;
+   size_t head = retro_atomic_load_acquire_size(&log_ring.head);
+   size_t seq  = since;
+
+   if (head > LOG_RING_SLOTS && seq < head - LOG_RING_SLOTS)
+      seq = head - LOG_RING_SLOTS;
+   if (seq > head)
+      seq = head;
+   *first = seq;
+   for (; seq < head; seq++)
+   {
+      size_t i, n;
+      size_t words[LOG_RING_WORDS];
+      struct log_ring_slot *slot = &log_ring.slots[seq % LOG_RING_SLOTS];
+      size_t stamp = retro_atomic_load_acquire_size(&slot->stamp);
+      /* still being written, or already a later line: skipped */
+      if (stamp != seq + 1)
+         continue;
+      for (i = 0; i < LOG_RING_WORDS; i++)
+         words[i] = retro_atomic_load_relaxed_size(&slot->text[i]);
+      retro_atomic_thread_fence_acquire();
+      if (retro_atomic_load_relaxed_size(&slot->stamp) != stamp)
+         continue;
+      ((char*)words)[sizeof(words) - 1] = '\0';
+      n = strlen((const char*)words);
+      if (_len + n + 2 > len)
+         break;
+      memcpy(s + _len, words, n);
+      _len += n;
+      if (!n || s[_len - 1] != '\n')
+         s[_len++] = '\n';
+   }
+   if (len)
+      s[_len < len ? _len : len - 1] = '\0';
+   *next = seq;
+   return _len;
+}
+#else
+#define verbosity_ring_put(line) ((void)0)
+#endif
+
 void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
 {
 #if defined(_XBOX1) || defined(__WINRT__)
@@ -421,6 +515,8 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
       const char *out   = rarch_log_line_format(line, sizeof(line),
             &heap, tag_v, fmt, ap);
 
+      verbosity_ring_put(out);
+
 #ifdef HAVE_COMPANION_WIMP
       /* Mirror the line into the desktop companion's log view, when
        * one is open. The companion now shows the tag too, and wide

verbosity.h

@@ -57,6 +57,18 @@ void retro_main_log_file_init(const char *path, bool append);
 
 bool is_logging_to_file(void);
 
+#ifdef HAVE_MCP
+/* The last lines logged, kept for GET_LOG once armed: lines are
+ * numbered from 0 as they are logged, and @since is the first wanted.
+ * Writes what fits of them to @s, one per line, and returns its
+ * length; *@next is the number of the line after the last written,
+ * and *@first that of the first, later than @since when older lines
+ * were overwritten. */
+void verbosity_ring_arm(void);
+size_t verbosity_ring_read(size_t since, char *s, size_t len,
+      size_t *first, size_t *next);
+#endif
+
 #if defined(HAVE_LOGGER)
 
 void logger_init (void);