ase/logging: simplify logging to logex() and log()

Signed-off-by: Tim Janik <[email protected]>
tim-janik · Nov 18, 2024 · 596950e · 596950e
1 parent 767e6e6
commit 596950e
Show file tree

Hide file tree

Showing 7 changed files with 93 additions and 110 deletions.
diff --git a/ase/driver.cc b/ase/driver.cc
@@ -183,10 +183,10 @@ PcmDriver::open (const String &devid, IODir desired, IODir required, const PcmDr
             !(entry.priority & 0x0000ffff))     // ignore secondary devices during auto-selection
           {
             PcmDriverP pcm_driver = RegisteredDriver<PcmDriverP>::open (entry.devid, desired, ep, opener);
-            loginf ("PcmDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
+            log ("PcmDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
             if (!pcm_driver && required && desired != required) {
               pcm_driver = RegisteredDriver<PcmDriverP>::open (entry.devid, required, ep, opener);
-              loginf ("PcmDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
+              log ("PcmDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
             }
             if (pcm_driver)
               return pcm_driver;
@@ -243,7 +243,7 @@ MidiDriver::open (const String &devid, IODir iodir, Error *ep)
         if (entry.priority < PSEUDO)    // ignore pseudo devices during auto-selection
           {
             MidiDriverP midi_driver = RegisteredDriver<MidiDriverP>::open (entry.devid, iodir, ep, opener);
-            loginf ("MidiDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
+            log ("MidiDriver::open: devid=%s: %s\n", entry.devid, ase_error_blurb (*ep));
             if (midi_driver)
               return midi_driver;
           }

diff --git a/ase/engine.cc b/ase/engine.cc
@@ -734,7 +734,7 @@ AudioEngine::update_drivers (const String &pcm_name, uint latency_ms, const Stri
                       PcmDriver::open (dset.pcm_name, Driver::WRITEONLY, Driver::WRITEONLY, pcm_config, &er);
     if (!dset.pcm_driver || er != 0) {
       dset.pcm_driver = dset.null_pcm_driver;
-      logerr ("Audio Driver", "Failed to open audio device: %s: %s", dset.pcm_name, ase_error_blurb (er));
+      logex ("Audio Driver: Failed to open audio device: %s: %s", dset.pcm_name, ase_error_blurb (er));
       const String errmsg = string_format ("# Audio I/O Error\n" "Failed to open audio device:\n" "%s:\n" "%s",
                                            dset.pcm_name, ase_error_blurb (er));
       engine_thread.queue_user_note ("driver.pcm", UserNote::CLEAR, errmsg);

diff --git a/ase/logging.cc b/ase/logging.cc
@@ -2,100 +2,71 @@
 #include "logging.hh"
 #include "platform.hh"
 #include "path.hh"
-#include <stdarg.h>
+#include <cstdarg>
+#include <cstring>
 #include <dirent.h>
 #include <fcntl.h>
 #include <unistd.h>
 #include <sys/stat.h>
 
 namespace Ase {
 
-static uint64 logstart_timestamp = 0;
-static constexpr double USEC2SEC = 1.0 / 1000000;
-static bool info2stderr = true;
-static int log_fd = -1;
-
-static std::array<int,2>
-log_fds (bool iserror)
+uint64_t
+timestamp_now ()
 {
-  if (!logstart_timestamp)
-    logstart_timestamp = timestamp_startup();
-  return { info2stderr || iserror ? 2 : -1, log_fd };
+  struct timeval tv = { 0, 0 };
+  gettimeofday (&tv, nullptr);
+  return tv.tv_sec * 1000000ULL + tv.tv_usec;
 }
 
-static char*
-sntime (char *buffer, size_t bsize)
-{
-  buffer[0] = 0;
-  snprintf (buffer, bsize, "[%+11.6f] ", USEC2SEC * (timestamp_realtime() - logstart_timestamp));
-  return buffer + strlen (buffer);
-}
+static uint64 programstart_timestamp = timestamp_now();
+static bool log_started = false;
 
-static String
-ilog_dir (bool mkdirs = false)
+static void
+logstart()
 {
-  const String ilogdir = Path::join (Path::xdg_dir ("CACHE"), "anklang");
-  if (mkdirs)
-    Path::mkdirs (ilogdir);
-  return ilogdir;
+  if (log_started) [[likely]] return;
+  log_started = timestamp_now();
+  const time_t now = programstart_timestamp / 1000000;
+  struct tm stm{};
+  localtime_r (&now, &stm);
+  char tbuf[128] = { 0, };
+  strftime (tbuf, sizeof (tbuf) - 1, "%Y-%m-%d %H:%M:%S %z", &stm);
+  const std::string exec = executable_path();
+  const char *bexec = strrchr (exec.c_str(), '/');
+  bexec = bexec ? bexec+1 : exec.c_str();
+  std::string msg = std::string (bexec) + ": programstart=\"" + tbuf + "\" executable=\"" + executable_path() + "\"";
+  logmsg (msg, {});
 }
 
 void
-log_setup (bool inf2stderr, bool log2file)
-{
-  if (log_fd >= 0) return;
-  info2stderr = inf2stderr;
-  if (log2file) {
-    const String dir = ilog_dir (true);
-    const String fname = string_format ("%s/%s-%08x.log", dir, program_alias(), gethostid());
-    errno = EBUSY;
-    const int OFLAGS = O_CREAT | O_EXCL | O_WRONLY | O_NOCTTY | O_NOFOLLOW | O_CLOEXEC; // O_TRUNC
-    const int OMODE = 0640;
-    int fd = open (fname.c_str(), OFLAGS, OMODE);
-    if (fd < 0 && errno == EEXIST) {
-      const String oldname = fname + ".old";
-      if (rename (fname.c_str(), oldname.c_str()) < 0)
-        perror (string_format ("%s: failed to rename \"%s\"", program_alias(), oldname.c_str()).c_str());
-      fd = open (fname.c_str(), OFLAGS, OMODE);
-    }
-    if (fd < 0)
-      perror (string_format ("%s: failed to open log file \"%s\"", program_alias(), fname.c_str()).c_str());
-    else {
-      log_fd = fd;
-      const auto lfds = log_fds (false); // does on demand setup
-      if (lfds[1] >= 0) {
-        constexpr const int MAXBUFFER = 1024;
-        char buffer[MAXBUFFER] = { 0, }, *b = sntime (buffer, MAXBUFFER);
-        snprintf (b, MAXBUFFER - (b - buffer),
-                  "%s %s: pid=%u startup=%.6f\n",
-                  program_alias().c_str(), ase_build_id(),
-                  getpid(), USEC2SEC * logstart_timestamp);
-        write (lfds[1], buffer, strlen (buffer));
-      }
-    }
-  }
-}
-
-void
-logmsg (const char c, const String &dept, const String &msg)
+logmsg (const std::string &msg, const std::source_location &loc)
 {
+  logstart();
   ScopedPosixLocale posix_locale; // use POSIX locale for this scope
   if (msg.empty()) return;
   String s = msg;
   if (s[s.size()-1] != '\n')
     s += "\n";
-  if (c == 'E')
-    s = dept + (dept.empty() ? "" : " ") + "Error: " + s;
-  else if (!dept.empty())
-    s = dept + ": " + s;
-  for (auto fd : log_fds (c == 'E')) {
-    if (fd == 1) fflush (stdout);
-    if (fd == 2) fflush (stderr);
-    if (c == 'T' && fd <= 2)
-      continue;
-    write (fd, s.data(), s.size());
-    // fdatasync (fd);
+  {
+    char tstamp[64] = { 0, };
+    snprintf (tstamp, sizeof (tstamp) - 1, "%.6f: ", 0.000001 * (timestamp_now() - programstart_timestamp));
+    s = tstamp + s;
+  }
+  const char *const filename = loc.file_name();
+  if (filename && filename[0]) {
+    char linein[128] = { 0, };
+    snprintf (linein, sizeof (linein) - 1, ":%u:%u: execution at: ", loc.line(), loc.column());
+    s = filename + std::string (linein) + loc.function_name() + "\n" + s;
   }
+  fflush (stderr);
+  write (2, s.data(), s.size());
+  // fdatasync (2);
+}
+
+void
+log_setup (bool inf2stderr, bool log2file)
+{
 }
 
 } // Ase
diff --git a/ase/logging.hh b/ase/logging.hh
@@ -1,41 +1,53 @@
 // This Source Code Form is licensed MPL-2.0: http://mozilla.org/MPL/2.0
 #pragma once
 
-#include <ase/strings.hh>
+#include <ase/formatter.hh>
+#include <source_location>
 
 namespace Ase {
 
-/// Write a string_format() message to the log file (or possibly stderr), using the POSIX/C locale.
-template<class... A> void loginf    (const char *format, const A &...args) ASE_PRINTF (1, 0);
+/// Wrap a string together with its source code location
+struct LString : public std::string {
+  std::source_location location;
+  LString (const std::string &s, std::source_location l = std::source_location::current()) :
+    std::string (s),
+    location (l)
+  {}
+  LString (const char *s, std::source_location l = std::source_location::current()) :
+    std::string (s),
+    location (l)
+  {}
+};
 
-/// Format and send a log message to the user, stderr and log file, using the POSIX/C locale.
-template<class... A> void logerr    (const String &dept, const char *format, const A &...args) ASE_PRINTF (2, 0);
+// Current time in µseconds.
+uint64_t                        timestamp_now   ();
+
+/// Write a log message to the log file (or possibly stderr), using the POSIX/C locale.
+template<class... A> void       log             (const char *format, const A &...args) __attribute__ ((__noinline__, __format__ (__printf__, 1, 0)));
+
+/// Write a log message to the log with source code location.
+template<class... A> void       logex           (const LString &format, const A &...args) __attribute__ ((__noinline__));
 
 /// Open log file.
-void                      log_setup (bool inf2stderr, bool log2file);
+void                            log_setup       (bool inf2stderr, bool log2file);
 
-// == Impl ==
-void logmsg (const char c, const String &dept, const String &msg);
+#ifdef _MATH_H
+using ::log;
+#endif
 
-/// Log text into logfile only.
-template<class... A> void
-logtxt (const char *format, const A &...args)
-{
-  logmsg ('T', "", string_format (format, args...).c_str());
-}
+// == implementations ==
+void logmsg (const std::string &msg, const std::source_location &loc);
 
-/// Log info to logfile (and stderr for some configs)
-template<class... A> void
-loginf (const char *format, const A &...args)
+template<class... A> __attribute__ ((__noinline__)) void
+log (const char *format, const A &...args)
 {
-  logmsg ('I', "", string_format (format, args...).c_str());
+  logmsg (string_format (format, args...), {});
 }
 
-/// Log error to stderr and logfile.
-template<class... A> void
-logerr (const String &dept, const char *format, const A &...args)
+template<class... A> __attribute__ ((__noinline__)) void
+logex (const LString &format, const A &...args)
 {
-  logmsg ('E', dept, string_format (format, args...).c_str());
+  logmsg (string_format (format.c_str(), args...), format.location);
 }
 
 } // Ase
diff --git a/ase/main.cc b/ase/main.cc
@@ -326,7 +326,7 @@ handle_autostop (const LoopState &state)
     case LoopState::PREPARE:    return seen_autostop;
     case LoopState::CHECK:      return seen_autostop;
     case LoopState::DISPATCH:
-      loginf ("stopping playback (auto)");
+      log ("Main: stopping playback (auto)");
       atquit_run (0);
       return true; // keep alive
     default: ;
@@ -535,7 +535,7 @@ main (int argc, char *argv[])
       Error error = Error::NO_MEMORY;
       if (preload_project)
         error = preload_project->load_project (filename);
-      loginf ("load project: %s: %s", filename, ase_error_blurb (error));
+      log ("Main: load project: %s: %s", filename, ase_error_blurb (error));
       if (!!error)
         warning ("%s: failed to load project: %s", filename, ase_error_blurb (error));
     }
@@ -554,7 +554,7 @@ main (int argc, char *argv[])
   if (main_config.mode == MainConfig::SYNTHENGINE) {
     const char *host = "127.0.0.1";
     wss->listen (host, xport, [] () { main_loop->quit (-1); });
-    loginf ("listen on: %s:%u", host, xport);
+    log ("Main: listen on: %s:%u", host, xport);
   }
   const String url = wss->url() + (subprotocol.empty() ? "" : "?subprotocol=" + subprotocol);
   if (embedding_fd < 0 && !url.empty())
@@ -563,7 +563,7 @@ main (int argc, char *argv[])
   // run atquit handler on SIGHUP SIGINT
   for (int sigid : { SIGHUP, SIGINT }) {
     main_loop->exec_usignal (sigid, [] (int8 sig) {
-      loginf ("got signal %d: aborting", sig);
+      log ("Main: got signal %d: aborting", sig);
       atquit_run (-1);
       return false;
     });
@@ -572,7 +572,7 @@ main (int argc, char *argv[])
 
   // catch SIGUSR2 to close sockets
   main_loop->exec_usignal (SIGUSR2, [wss] (int8 sig) {
-    loginf ("got signal %d: reset WebSocket", sig);
+    log ("Main: got signal %d: reset WebSocket", sig);
     wss->reset();
     return true;
   });
@@ -587,7 +587,7 @@ main (int argc, char *argv[])
           {
             ssize_t n = read (embedding_fd, &msg[0], msg.size()); // flush input
             msg.resize (n > 0 ? n : 0);
-            loginf ("Embedder Msg: %s", msg);
+            log ("Main: Embedder Msg: %s", msg);
           }
         if (string_strip (msg) == "QUIT" || (pfd.revents & (PollFD::ERR | PollFD::HUP | PollFD::NVAL)))
           wss->shutdown();
@@ -606,7 +606,7 @@ main (int argc, char *argv[])
   if (config.outputfile)
     {
       std::shared_ptr<CallbackS> callbacks = std::make_shared<CallbackS>();
-      loginf ("Start caputure: %s", config.outputfile);
+      log ("Main: Start caputure: %s", config.outputfile);
       config.engine->queue_capture_start (*callbacks, config.outputfile, true);
       auto job = [callbacks] () {
         for (const auto &callback : *callbacks)
@@ -618,7 +618,7 @@ main (int argc, char *argv[])
   // start auto play
   if (config.play_autostart && preload_project)
     main_loop->exec_idle ([preload_project] () {
-      loginf ("starting playback (auto)");
+      log ("Main: starting playback (auto)");
       preload_project->start_playback (config.play_autostop);
     });
   // handle automatic shutdown
@@ -631,7 +631,7 @@ main (int argc, char *argv[])
   // run main event loop and catch SIGUSR2
   const int exitcode = main_loop->run();
   assert_return (main_loop, -1); // ptr must be kept around
-  logtxt ("main loop quit (code=%d)", exitcode);
+  log ("Main: event loop quit (code=%d)", exitcode);
 
   // cleanup
   wss->shutdown(); // close socket, allow no more calls
@@ -644,7 +644,7 @@ main (int argc, char *argv[])
   main_loop->iterate_pending();
   main_config_.engine = nullptr;
 
-  logtxt ("exiting: %d", exitcode);
+  logex ("Main: exiting: %d", exitcode);
   return exitcode;
 }
 

diff --git a/ase/project.cc b/ase/project.cc
@@ -476,7 +476,7 @@ ProjectImpl::match_serialized (const String &regex, int group)
   String json;
   Error error = snapshot_project (json);
   if (!!error) {
-    logerr ("failed to serialize project: %s\n", ase_error_blurb (error));
+    logex ("Project: failed to serialize project: %s\n", ase_error_blurb (error));
     return "";
   }
   return Re::grep (regex, json, group);

diff --git a/ase/regex.cc b/ase/regex.cc
@@ -71,7 +71,7 @@ Re::grep (const String &regex, const String &input, int group, Flags flags)
     | PCRE2_NEVER_BACKSLASH_C;  // prevent matching point in the middle of UTF-8
   pcre2_code *rx = pcre2_compile ((const uint8_t*) regex.c_str(), PCRE2_ZERO_TERMINATED, COMPILE_OPTIONS, &errorcode, &erroroffset, ccontext);
   if (!rx) {
-    logerr ("Re", "failed to compile regex (%d): %s", errorcode, regex);
+    logex ("Re", "failed to compile regex (%d): %s", errorcode, regex);
     return "";
   }
   pcre2_match_data *md = pcre2_match_data_create_from_pattern (rx, NULL);