Skip to content

Commit

Permalink
Merge branch 'log2file'
Browse files Browse the repository at this point in the history
* Branch commit log:
  package.json: add --log2file to synth engine
  electron/main.js: add --log2file to synth engine
  ase/utils.hh: include ase/logging.hh
  ase/main: add --log2file and log info of interest
  ase/engine.cc: log missing PCM driver as error
  ase/driver.cc: log driver opening as info
  ase/logging: add log_setup(), loginf() and logerr()
  ase/logging: add source files for logging

Signed-off-by: Tim Janik <[email protected]>
  • Loading branch information
tim-janik committed May 20, 2024
2 parents 80ed0d5 + b6fcbdc commit f4a6e2d
Show file tree
Hide file tree
Showing 9 changed files with 188 additions and 26 deletions.
6 changes: 5 additions & 1 deletion ase/driver.cc
Original file line number Diff line number Diff line change
Expand Up @@ -181,8 +181,11 @@ 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);
if (!pcm_driver && required && desired != required)
loginf ("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));
}
if (pcm_driver)
return pcm_driver;
}
Expand Down Expand Up @@ -238,6 +241,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));
if (midi_driver)
return midi_driver;
}
Expand Down
1 change: 1 addition & 0 deletions ase/engine.cc
Original file line number Diff line number Diff line change
Expand Up @@ -733,6 +733,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));
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);
Expand Down
98 changes: 98 additions & 0 deletions ase/logging.cc
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
// This Source Code Form is licensed MPL-2.0: http://mozilla.org/MPL/2.0
#include "logging.hh"
#include "platform.hh"
#include "path.hh"
#include <stdarg.h>
#include <dirent.h>
#include <fcntl.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)
{
if (!logstart_timestamp)
logstart_timestamp = timestamp_startup();
return { info2stderr || iserror ? 2 : -1, log_fd };
}

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 String
ilog_dir (bool mkdirs = false)
{
const String ilogdir = Path::join (Path::xdg_dir ("CACHE"), "anklang");
if (mkdirs)
Path::mkdirs (ilogdir);
return ilogdir;
}

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)
{
Lib::ScopedPosixLocale posix_locale_scope; // push 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);
write (fd, s.data(), s.size());
// fdatasync (fd);
}
}

} // Ase
30 changes: 30 additions & 0 deletions ase/logging.hh
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
// This Source Code Form is licensed MPL-2.0: http://mozilla.org/MPL/2.0
#pragma once

#include <ase/strings.hh>

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);

/// 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);

/// Open log file.
void log_setup (bool inf2stderr, bool log2file);

// == Impl ==
void logmsg (const char c, const String &dept, const String &msg);
template<class... A> void
loginf (const char *format, const A &...args)
{
logmsg ('I', "", string_format (format, args...).c_str());
}
template<class... A> void
logerr (const String &dept, const char *format, const A &...args)
{
logmsg ('E', dept, string_format (format, args...).c_str());
}

} // Ase
72 changes: 49 additions & 23 deletions ase/main.cc
Original file line number Diff line number Diff line change
Expand Up @@ -99,8 +99,6 @@ print_usage (bool help)
}
printout ("Usage: %s [OPTIONS] [project.anklang]\n", executable_name());
printout (" --check Run integrity tests\n");
printout (" --test[=test] Run specific tests\n");
printout (" --list-tests List all test names\n");
printout (" --class-tree Print exported class tree\n");
printout (" --disable-randomization Test mode for deterministic tests\n");
printout (" --embed <fd> Parent process socket for embedding\n");
Expand All @@ -110,14 +108,17 @@ print_usage (bool help)
printout (" --jsbin Print Javascript IPC & binary messages\n");
printout (" --jsipc Print Javascript IPC messages\n");
printout (" --list-drivers Print PCM and MIDI drivers\n");
printout (" -P pcmdriver Force use of <pcmdriver>\n");
printout (" -M mididriver Force use of <mididriver>\n");
printout (" --list-tests List all test names\n");
printout (" --log2file Enable logging to ~/.cache/anklang/ instead of stderr\n");
printout (" --norc Prevent loading of any rc files\n");
printout (" -o wavfile Capture output to OPUS/FLAC/WAV file\n");
printout (" --play-autostart Automatically start playback of `project.anklang`\n");
printout (" --rand64 Produce 64bit random numbers on stdout\n");
printout (" -t <time> Automatically play and stop after <time> has passed\n"); // -t <time>[{,|;}tailtime]
printout (" --test[=test] Run specific tests\n");
printout (" --version Print program version\n");
printout (" -M mididriver Force use of <mididriver>\n");
printout (" -P pcmdriver Force use of <pcmdriver>\n");
printout (" -o wavfile Capture output to OPUS/FLAC/WAV file\n");
printout (" -t <time> Automatically play and stop after <time> has passed\n"); // -t <time>[{,|;}tailtime]
}

// 1:ERROR 2:FAILED+REJECT 4:IO 8:MESSAGE 16:GET 256:BINARY
Expand All @@ -137,7 +138,7 @@ parse_args (int *argcp, char **argv)
config.jsonapi_logflags |= debug_key_enabled ("jsipc") ? jsipc_logflags : 0;
}

bool norc = false;
config.norc = false;
bool sep = false; // -- separator
const uint argc = *argcp;
for (uint i = 1; i < argc; i++)
Expand All @@ -149,7 +150,9 @@ parse_args (int *argcp, char **argv)
else if (strcmp ("--disable-randomization", argv[i]) == 0)
config.allow_randomization = false;
else if (strcmp ("--norc", argv[i]) == 0)
norc = true;
config.norc = true;
else if (strcmp ("--log2file", argv[i]) == 0)
config.log2file = true;
else if (strcmp ("--rand64", argv[i]) == 0)
{
FastRng prng;
Expand Down Expand Up @@ -264,9 +267,6 @@ parse_args (int *argcp, char **argv)
}
*argcp = e;
}
// load preferences unless --norc was given
if (!norc)
Preference::load_preferences (true);
return config;
}

Expand Down Expand Up @@ -326,6 +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)");
atquit_run (0);
return true; // keep alive
default: ;
Expand Down Expand Up @@ -441,12 +442,16 @@ main (int argc, char *argv[])
main_loop = MainLoop::create();
// handle loft preallocation needs
main_loop->exec_dispatcher (dispatch_loft_lowmem, EventLoop::PRIORITY_CEILING);
// handle automatic shutdown
main_loop->exec_dispatcher (handle_autostop);

// setup thread and handle args and config (needs main_loop)
// parse args and config (needs main_loop)
main_config_ = parse_args (&argc, argv);
const MainConfig &config = main_config_;
// configure logging
log_setup (!config.log2file, config.log2file);

// load preferences unless --norc was given
if (!config.norc)
Preference::load_preferences (true);

const auto B1 = color (BOLD);
const auto B0 = color (BOLD_OFF);
Expand Down Expand Up @@ -530,6 +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));
if (!!error)
warning ("%s: failed to load project: %s", filename, ase_error_blurb (error));
}
Expand All @@ -545,18 +551,31 @@ main (int argc, char *argv[])
const int xport = embedding_fd >= 0 ? 0 : 1777;
const String subprotocol = xport ? "" : make_auth_string();
jsonapi_require_auth (subprotocol);
if (main_config.mode == MainConfig::SYNTHENGINE)
wss->listen ("127.0.0.1", xport, [] () { main_loop->quit (-1); });
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);
}
const String url = wss->url() + (subprotocol.empty() ? "" : "?subprotocol=" + subprotocol);
if (embedding_fd < 0 && !url.empty())
printout ("%sLISTEN:%s %s\n", B1, B0, url);

// run atquit handler on SIGINT
main_loop->exec_usignal (SIGINT, [] (int8 sig) { atquit_run (-1); return false; });
USignalSource::install_sigaction (SIGINT);
// run atquit handler on SIGHUP SIGINT
for (int sigid : { SIGHUP, SIGINT }) {
main_loop->exec_usignal (sigid, [] (int8 sig) {
loginf ("got signal %d: aborting", sig);
atquit_run (-1);
return false;
});
USignalSource::install_sigaction (sigid);
}

// catch SIGUSR2 to close sockets
main_loop->exec_usignal (SIGUSR2, [wss] (int8) { wss->reset(); return true; });
main_loop->exec_usignal (SIGUSR2, [wss] (int8 sig) {
loginf ("got signal %d: reset WebSocket", sig);
wss->reset();
return true;
});
USignalSource::install_sigaction (SIGUSR2);

// monitor and allow auth over keep-alive-fd
Expand All @@ -568,8 +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);
if (!msg.empty())
printerr ("Embedder: %s%s", msg, msg.back() == '\n' ? "" : "\n");
loginf ("Embedder Msg: %s", msg);
}
if (string_strip (msg) == "QUIT" || (pfd.revents & (PollFD::ERR | PollFD::HUP | PollFD::NVAL)))
wss->shutdown();
Expand All @@ -588,6 +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);
config.engine->queue_capture_start (*callbacks, config.outputfile, true);
auto job = [callbacks] () {
for (const auto &callback : *callbacks)
Expand All @@ -598,7 +617,12 @@ main (int argc, char *argv[])

// start auto play
if (config.play_autostart && preload_project)
main_loop->exec_idle ([preload_project] () { preload_project->start_playback (config.play_autostop); });
main_loop->exec_idle ([preload_project] () {
loginf ("starting playback (auto)");
preload_project->start_playback (config.play_autostop);
});
// handle automatic shutdown
main_loop->exec_dispatcher (handle_autostop);

// run test suite
if (main_config.mode == MainConfig::CHECK_INTEGRITY_TESTS)
Expand All @@ -607,6 +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
loginf ("main loop quit (code=%d)", exitcode);

// cleanup
wss->shutdown(); // close socket, allow no more calls
Expand All @@ -619,6 +644,7 @@ main (int argc, char *argv[])
main_loop->iterate_pending();
main_config_.engine = nullptr;

loginf ("exiting: %d", exitcode);
return exitcode;
}

Expand Down
2 changes: 2 additions & 0 deletions ase/main.hh
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@ struct MainConfig {
std::vector<String> args;
uint16 websocket_port = 0;
int jsonapi_logflags = 1;
bool norc = true;
bool log2file = false;
bool allow_randomization = true;
bool list_drivers = false;
bool play_autostart = false;
Expand Down
2 changes: 1 addition & 1 deletion ase/utils.hh
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
#define __ASE_UTILS_HH__

#include <ase/defs.hh>
#include <ase/strings.hh>
#include <ase/logging.hh>
#include <experimental/type_traits>
#include <any>

Expand Down
1 change: 1 addition & 0 deletions electron/main.js
Original file line number Diff line number Diff line change
Expand Up @@ -156,6 +156,7 @@ function start_sound_engine (config, datacb)
}
const { spawn, spawnSync } = require ('child_process');
const args = [ '--embed', '3' ];
args.push ('--log2file');
if (config.verbose)
args.push ('--verbose');
if (config.binary)
Expand Down
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
"type": "module",
"scripts": {
"serve": "exec run-p sound-engine monitor",
"sound-engine": "exec out/lib/AnklangSynthEngine $ASEOPT",
"sound-engine": "exec out/lib/AnklangSynthEngine --log2file $ASEOPT",
"monitor": "exec nodemon --ext '*' --watch ui/ --delay 370ms --on-change-only --exec 'npm run -s ui/rebuild' --exitcrash",
"ui/rebuild": "exec make ui/rebuild -j`nproc`"
},
Expand Down

0 comments on commit f4a6e2d

Please sign in to comment.