verbosity: flush every log line again

4552975f37 stopped flushing INFO/DEBUG lines to the log file and only
flushed [ERROR] and [WARN], to save the per-line fflush cost. In
practice that costs more than it saves:

- When RetroArch crashes, the lines that explain the crash are
  usually the informational ones written just before it. Those were
  exactly the lines left sitting in stdio's buffer and lost, which
  makes crash reports much harder to read in the cases where gdb
  does not help.
- Anything following the log live (tail -f, monitoring scripts) saw
  nothing until the buffer happened to fill (#19571).

Go back to the previous behaviour: one write and one flush per line,
for every tag. rarch_log_tag_wants_flush() and the flush parameter on
rarch_log_line_emit() are removed. The strcmp tag matching for the
Android log priority from afd57d615e stays - that overread fix is
independent of the flush policy.

The log-atomicity harness's flush lane now asserts the promise that
matters: a RARCH_LOG (informational) line must be readable from the
file as soon as the call returns, before any deinit.

Fixes #19571

samples/frontend/log_atomicity/log_atomicity_test.c

@@ -150,13 +150,11 @@ int main(int argc, char *argv[])
    if (ta) sthread_join(ta);
    if (tb) sthread_join(tb);
 
-   /* Flush-policy lane: an error line is durable the moment the
-    * call returns - readable from the file before any deinit -
-    * while informational lines may ride stdio's buffer until the
-    * next flush point (their presence mid-run is therefore not
-    * asserted either way; the whole-file scan below still counts
-    * every line after deinit's fclose flushes the tail). */
-   RARCH_ERR("flush-lane error line\n");
+   /* Flush-policy lane: every line, whatever its tag, is durable the
+    * moment the call returns - readable from the file before any
+    * deinit. The informational line is the one that matters: it is
+    * what a crash log's tail and a live follower both depend on. */
+   RARCH_LOG("flush-lane info line\n");
    {
       FILE *ef;
       int   found = 0;
@@ -166,13 +164,13 @@ int main(int argc, char *argv[])
          size_t  ecap     = 0;
          ssize_t elen;
          while ((elen = getline(&eline, &ecap, ef)) != -1)
-            if (strstr(eline, "flush-lane error line"))
+            if (strstr(eline, "flush-lane info line"))
                found = 1;
          free(eline);
          fclose(ef);
       }
       CHECK(found,
-            "RARCH_ERR line not durable before deinit (flush policy)");
+            "RARCH_LOG line not durable before deinit (flush policy)");
    }
 
    retro_main_log_file_deinit();
@@ -188,7 +186,7 @@ int main(int argc, char *argv[])
       while ((n = getline(&line, &line_cap, f)) > 0)
       {
          /* The flush-policy lane's marker line has its own shape. */
-         if (strstr(line, "flush-lane error line"))
+         if (strstr(line, "flush-lane info line"))
             continue;
          size_t len = (size_t)n;
          char which;

verbosity.c

@@ -305,28 +305,15 @@ static const char *rarch_log_line_format(char *line, size_t line_size,
    return line;
 }
 
-/* Errors and warnings must survive a crash whose report they may be,
- * so their lines reach the OS before this returns. Informational
- * traffic rides stdio's buffer - the per-line flush was the file
- * sink's dominant cost - and becomes durable at the flush points:
- * rarch_log_file_deinit()'s fclose, and any later flushed line on
- * the same stream. The cost of that ride is the documented one: a
- * hard crash can lose the buffered tail of INFO/DEBUG lines written
- * after the last error or warning. Tags are matched by exact label;
- * a core-supplied custom tag rides the buffer like INFO. */
-static bool rarch_log_tag_wants_flush(const char *tag_v)
-{
-   /* strcmp, not memcmp with the pattern's sizeof: the tag can be a
-    * shorter string than the pattern ("[WARN]" against "[ERROR]"'s
-    * eight bytes), and a sized compare reads past its terminator -
-    * a one-byte overread AddressSanitizer stops the process for. */
-   return strcmp(tag_v, FILE_PATH_LOG_ERROR) == 0
-       || strcmp(tag_v, FILE_PATH_LOG_WARN)  == 0;
-}
-
-/* One write - and, for lines that must not wait, one flush - under
- * the LibNX mutex where it exists. */
-static void rarch_log_line_emit(FILE *fp, const char *out, bool flush)
+/* One write, one flush, under the LibNX mutex where it exists.
+ *
+ * The flush is unconditional, for every tag. Buffering informational
+ * lines was tried and taken back out: a log is read after a crash, and
+ * the lines that explain it are usually the INFO/DEBUG ones written
+ * just before it - exactly the tail a buffer loses - and anything
+ * following the log live (tail -f, a monitoring script) sees nothing
+ * until the buffer happens to fill. */
+static void rarch_log_line_emit(FILE *fp, const char *out)
 {
 #if defined(HAVE_LIBNX)
    /* Around exactly one write and its flush; libnx newlib's stdio
@@ -334,8 +321,7 @@ static void rarch_log_line_emit(FILE *fp, const char *out, bool flush)
    mutexLock(&main_verbosity_st.mtx);
 #endif
    fputs(out, fp);
-   if (flush)
-      fflush(fp);
+   fflush(fp);
 #if defined(HAVE_LIBNX)
    mutexUnlock(&main_verbosity_st.mtx);
 #endif
@@ -353,7 +339,7 @@ static void rarch_log_line_write(FILE *fp, const char *tag_v,
    const char *out = rarch_log_line_format(line, sizeof(line), &heap,
          tag_v, fmt, ap);
 
-   rarch_log_line_emit(fp, out, rarch_log_tag_wants_flush(tag_v));
+   rarch_log_line_emit(fp, out);
    free(heap);
 }
 #endif
@@ -401,8 +387,8 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
          int prio = ANDROID_LOG_INFO;
          if (tag)
          {
-            /* strcmp for the same reason as rarch_log_tag_wants_flush:
-             * a sized memcmp reads past a shorter tag's terminator. */
+            /* strcmp, not memcmp with the pattern's sizeof: a sized
+             * compare reads past a shorter tag's terminator. */
             if (strcmp(tag, FILE_PATH_LOG_WARN) == 0)
                prio = ANDROID_LOG_WARN;
             else if (strcmp(tag, FILE_PATH_LOG_ERROR) == 0)
@@ -444,8 +430,7 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
           * guard, every line would print twice in the no-file case. */
          printf("%s", out);
          if (main_verbosity_st.initialized && fp)
-            rarch_log_line_emit(fp, out,
-                  rarch_log_tag_wants_flush(tag_v));
+            rarch_log_line_emit(fp, out);
 
 #else
          {
@@ -477,8 +462,7 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
 #endif
 
             if (main_verbosity_st.initialized && fp)
-               rarch_log_line_emit(fp, out,
-                     rarch_log_tag_wants_flush(tag_v));
+               rarch_log_line_emit(fp, out);
          }
 #endif
       }
@@ -488,8 +472,7 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap)
          /* stdio's per-call lock keeps the single write whole under
           * concurrent writers; the format above already took the
           * heap detour for wide lines. */
-         rarch_log_line_emit(fp, out,
-               rarch_log_tag_wants_flush(tag_v));
+         rarch_log_line_emit(fp, out);
 #endif
 
       free(heap);