mcap/src/base/logger.jai

// Every thread logs through app_logger, which only queues the line: each thread is its own producer,
// tagged by its Thread (context.logger_data) and context.thread_index, onto one multi-producer,
// single-consumer queue (log_queue.jai). One writer thread, the queue's single consumer, formats
// each line once, writes it to the console and the log file, and hands it to the Event Log ring.
// A thread that logs never waits on the file, the ring or the Event Log panel.

LOG_SOURCE_LOCATION :: DEBUG;
APP_LOG_FILES_TO_KEEP :: 30;

LOGGER_WAKE_MS        :: 250;    // the writer's longest sleep, should a wake-up go astray
LOGGER_DRAIN_CHUNK    :: 1024;   // lines formatted and written per file write
LOGGER_CRASH_FLUSH_MS :: 1000;   // how long a crash waits for its report to reach the log file

Log_Level :: enum s32 {
  General :: 0;
  Warning :: 1;
  Error   :: 2;
  Fatal_Error :: 3;
}

// One logged line. A single allocation holds the struct and both strings, which point just past
// it. Queued by the thread that logged it, then owned by the writer, then by the Event Log ring.
Log_Message :: struct {
  using link: Mpsc_Node;   // first, so a queue node is the message
  timestamp: Apollo_Time;
  location: Source_Code_Location;
  flags: Log_Flags;
  user_flags: u32;
  level: Log_Level;
  thread_index: s64;
  thread_name: string;     // "" for an unnamed thread
  message: string;
}

logger: Logger;
Logger :: struct {
  // Producers.
  queue: Mpsc_Queue;
  wake: Semaphore;
  wake_pending: bool;      // a wake is signalled and not yet taken, so a burst signals once
  running: bool;           // lines go through the queue; otherwise app_logger writes the console only
  pushed: s64;             // lines ever queued

  // The writer, the queue's single consumer.
  writer: Thread;
  writer_started: bool;
  stopping: bool;
  written: s64;            // lines ever finished with; logger_flush waits on it
  inline_mutex: Mutex;     // without a writer thread, each producer drains under this instead
  start_timestamp: Apollo_Time;
  file_path: string;
  file: File;

  // The Event Log: written by the writer, read by the panel, each under ring_mutex.
  ring_mutex: Mutex;
  ring: Circle_Buffer(*Log_Message);
  dropped: s64;
  requested_capacity: s64; // set by any thread; the writer applies it
  clear_requested: bool;   // likewise

  // Panel state; the main thread only.
  text_filter: ImGui.TextFilter;
  show_general: bool = DEBUG;
  show_warnings: bool = DEBUG;
}

to_log_level :: (log_flags: Log_Flags) -> Log_Level {
  if log_flags == .NONE
    return .General;
  if log_flags & .WARNING == .WARNING
    return .Warning;
  if log_flags & .ERROR == .ERROR
    return .Error;

  // We're not handling the following flags:
  // CONTENT, TO_FILE_ONLY, VERBOSE_ONLY, VERY_VERBOSE_ONLY, TOPIC_ONLY
  return .General;
}

get_color :: (level: Log_Level) -> Vector4 {
  if #complete level == {
    case .General;     return app_theme.palette.accent_alt;
    case .Warning;     return app_theme.palette.warning;
    case .Error;       return app_theme.palette.error;
    case .Fatal_Error; return app_theme.palette.error_dim;
  }

  return app_theme.palette.dim;
}

// The producer side; any thread. data is context.logger_data: the logging thread's Thread, or
// null on the main thread and on a context made from scratch.
app_logger :: (message: string, data: *void, info: Log_Info) {
  if !atomic_load(*logger.running) {
    console_logger(message, info.common_flags, info.user_flags);
    return;
  }

  thread := cast(*Thread) data;
  name := ifx thread then thread.name else ifx context.thread_index == 0 then "main" else "";
  entry := log_message_new(message, name, context.thread_index, info);

  mpsc_push(*logger.queue, *entry.link);
  atomic_add(*logger.pushed, 1);

  if logger.writer_started {
    if !atomic_exchange(*logger.wake_pending, true)  signal(*logger.wake);
  } else {
    lock(*logger.inline_mutex);
    logger_drain();
    unlock(*logger.inline_mutex);
  }
}

use_app_logger :: (ctx: *#Context) #expand {
  if atomic_load(*logger.running)  ctx.logger = app_logger;
}

// Every thread made after init_logger logs as itself; Thread_Group workers and wavefront lanes too,
// since they are made by thread_init.
logger_thread_init :: (thread: *Thread) {
  thread.starting_context.logger      = app_logger;
  thread.starting_context.logger_data = thread;
}

init_logger :: () { using logger;
  if atomic_load(*running) then return;
  push_allocator(context.default_allocator);

  mpsc_init(*queue);
  init(*wake);
  init(*inline_mutex, "logger inline");
  init(*ring_mutex, "event log");
  ring.allocator = context.default_allocator;
  requested_capacity = EVENT_LOG_CAPACITY_DEFAULT;
  start_timestamp = current_time_consensus();

  context.logger      = app_logger;
  context.logger_data = null;
  thread_init_handler = logger_thread_init;
  crash_log_hook      = logger_crash_hook;
  atomic_store(*running, true);

  working_directory := app_install_directory();
  log_directory := tprint("%/%", working_directory, APP_LOG_DIRECTORY);
  file_path = sprint("%/%-%.log", log_directory, APP_FOLDER_NAME, format_datetime(start_timestamp,, temp));
  if !make_directory_if_it_does_not_exist(log_directory, recursive=true) {
    log_error("Failed to create the log directory %. Check permissions. Logging to the Event Log only.", log_directory);
  } else {
    success: bool;
    file, success = file_open(file_path, for_writing=true, log_errors=true);
    if !success  log_error("Failed to open the log file %. Logging to the Event Log only.", file_path);
    else         prune_files_keeping_newest(log_directory, tprint("%-", APP_FOLDER_NAME), ".log", APP_LOG_FILES_TO_KEEP);
  }

  if thread_init(*writer, logger_writer_proc, name = "logger") {
    writer_started = true;
    thread_start(*writer);
  } else {
    log_error("Could not start the logger thread; each thread will write its own lines.");
  }
  log("Logging through the % queue.", ifx writer_started then "logger thread's" else "inline");
}

close_logger :: () { using logger;
  if !atomic_load(*running)  return;
  push_allocator(context.default_allocator);

  if writer_started {
    atomic_store(*stopping, true);
    signal(*wake);
    thread_is_done(*writer, -1);
    thread_deinit(*writer);
    writer_started = false;
  }

  // From here a line goes straight to the console. With the writer gone this thread is the queue's
  // only consumer, so it takes whatever was queued before running dropped.
  atomic_store(*running, false);
  thread_init_handler = null;
  crash_log_hook      = null;
  context.logger      = runtime_support_default_logger;
  logger_drain();

  lock(*ring_mutex);
  for ring  free(it,, context.default_allocator);
  delete(*ring);
  unlock(*ring_mutex);

  if is_valid(file)  file_close(*file);
  string_free(file_path);
  file_path = "";
}

// Asks for the Event Log to keep at most capacity entries; any thread. The writer applies it.
logger_set_event_log_capacity :: (capacity: s64) {
  atomic_store(*logger.requested_capacity, clamp(capacity, EVENT_LOG_CAPACITY_MIN, EVENT_LOG_CAPACITY_MAX));
  logger_wake_writer();
}

// Waits, up to timeout_ms, for every line queued before the call to be written. For the moments the
// process may end before close_logger: a session ending, a signal, a crash.
logger_flush :: (timeout_ms: s64) {
  if !atomic_load(*logger.running) || !logger.writer_started  return;   // inline lines are written as they are logged
  if context.thread_index == logger.writer.index  return;                // the writer cannot wait on itself

  target := atomic_load(*logger.pushed);
  logger_wake_writer();
  start := current_time_monotonic();
  while atomic_load(*logger.written) < target {
    if to_milliseconds(current_time_monotonic() - start) >= timeout_ms  break;
    sleep_milliseconds(1);
  }
}

#scope_file

log_message_new :: (message: string, thread_name: string, thread_index: s64, info: Log_Info) -> *Log_Message {
  memory := cast(*u8) alloc(size_of(Log_Message) + thread_name.count + message.count,, context.default_allocator);
  entry := cast(*Log_Message) memory;
  memset(entry, 0, size_of(Log_Message));

  entry.timestamp    = current_time_consensus();
  entry.location     = info.location;
  entry.flags        = info.common_flags;
  entry.user_flags   = info.user_flags;
  entry.level        = to_log_level(info.common_flags);
  entry.thread_index = thread_index;

  text := memory + size_of(Log_Message);
  memcpy(text, thread_name.data, thread_name.count);
  entry.thread_name = .{thread_name.count, text};
  memcpy(text + thread_name.count, message.data, message.count);
  entry.message = .{message.count, text + thread_name.count};
  return entry;
}

logger_wake_writer :: () {
  if logger.writer_started && !atomic_exchange(*logger.wake_pending, true)  signal(*logger.wake);
}

logger_writer_proc :: (thread: *Thread) -> s64 {
  while true {
    wait_for(*logger.wake, LOGGER_WAKE_MS);
    atomic_store(*logger.wake_pending, false);   // before draining, so a line queued during it wakes us again
    stopping := atomic_load(*logger.stopping);
    logger_drain();
    if stopping  break;
  }
  return 0;
}

// The consumer side: the writer, the one producer holding inline_mutex, or close_logger once the
// writer has stopped. Takes everything queued, a chunk at a time.
logger_drain :: () {
  mark := get_temporary_storage_mark();
  defer set_temporary_storage_mark(mark);

  while true {
    batch: [..] *Log_Message;
    batch.allocator = temp;
    builder: String_Builder;
    builder.allocator = temp;

    while batch.count < LOGGER_DRAIN_CHUNK {
      node := mpsc_pop(*logger.queue);
      if !node  break;
      entry := cast(*Log_Message) node;
      log_format_line(*builder, entry);
      console_logger(entry.message, entry.flags, entry.user_flags);
      array_add(*batch, entry);
    }

    if is_valid(logger.file) && builder_string_length(*builder) {
      file_write(*logger.file, builder_to_string(*builder,, temp));
      #if OS != .WINDOWS  POSIX.fflush(logger.file.handle);   // WriteFile is already unbuffered
    }

    lock(*logger.ring_mutex);
    event_log_apply_requests();
    for batch {
      if it.flags & .TO_FILE_ONLY {
        free(it,, context.default_allocator);
        continue;
      }
      if event_log_insert(*logger.ring, it)  logger.dropped += 1;
    }
    unlock(*logger.ring_mutex);

    atomic_add(*logger.written, batch.count);
    if batch.count < LOGGER_DRAIN_CHUNK  break;
    set_temporary_storage_mark(mark);
  }
}

// Under ring_mutex, on the consumer.
event_log_apply_requests :: () { using logger;
  if atomic_exchange(*clear_requested, false) {
    for ring  free(it,, context.default_allocator);
    reset(*ring, overwrite=true);   // insert hands back a slot's old entry to free, so none may linger
    dropped = 0;
  }

  capacity := atomic_load(*requested_capacity);
  if capacity <= 0 || capacity == ring.allocated  return;

  dropped += event_log_resize(*ring, capacity);
  log("[logger] The Event Log keeps the newest % entries.", capacity);
}

#scope_export

// Adds entry, freeing the oldest when the ring is full. True when one was dropped.
event_log_insert :: (ring: *Circle_Buffer(*Log_Message), entry: *Log_Message) -> dropped: bool {
  oldest := insert(ring, entry);
  if !oldest  return false;
  free(oldest,, context.default_allocator);
  return true;
}

// Keeps the newest capacity entries and frees the rest. Returns how many were freed.
event_log_resize :: (ring: *Circle_Buffer(*Log_Message), capacity: s64) -> freed: s64 {
  // resize keeps the newest entries but drops the rest without freeing them, so free those first.
  excess := max(count(ring.*) - capacity, 0);
  for 0..excess-1  free(ring.*[it],, context.default_allocator);
  resize(ring, capacity);
  return excess;
}

#scope_file

logger_crash_hook :: (crash_report: string) {
  // Called from a #no_context crash too, whose fresh context has the default logger: queue it here.
  info: Log_Info;
  info.common_flags = .ERROR | .TO_FILE_ONLY;
  app_logger(crash_report, ifx context.logger == app_logger then context.logger_data else null, info);
  logger_flush(LOGGER_CRASH_FLUSH_MS);
}

log_thread_label :: (entry: *Log_Message) -> string {
  if entry.thread_name.count  return entry.thread_name;
  return tprint("thread %", entry.thread_index);
}

log_format_line :: (builder: *String_Builder, entry: *Log_Message) {
  #if LOG_SOURCE_LOCATION {
    print_to_builder(builder, "[%, %:%] ", format_datetime(entry.timestamp,, temp), entry.location.fully_pathed_filename, entry.location.line_number);
  } else {
    print_to_builder(builder, "[%] ", format_datetime(entry.timestamp,, temp));
  }
  print_to_builder(builder, "[%] ", log_thread_label(entry));
  if entry.flags != .NONE  print_to_builder(builder, "[%] ", entry.flags);
  append(builder, entry.message);
  if !entry.message.count || entry.message[entry.message.count-1] != #char "\n"  append(builder, "\n");
}

console_logger :: (message: string, common_flags: Log_Flags, user_flags: u32) {
    if !message then return;

    to_standard_error := (common_flags & .ERROR) != 0;

    color := Console_Color.WHITE;
    if user_flags {
        color = PROGRAM_LOG_FLAGS_COLOR[user_flags];
    } else {
             if common_flags & .ERROR              color = COLOR_ERROR;
        else if common_flags & .WARNING            color = COLOR_WARNING;
        else if common_flags & .VERBOSE_ONLY       color = COLOR_DEBUG;
        else if common_flags & .VERY_VERBOSE_ONLY  color = COLOR_TRACE;
    }

    with_console_color(color, #code {
        if message[message.count-1] != #char "\n" {
            write_strings(message, "\n", to_standard_error = to_standard_error);
        } else {
            write_string(message, to_standard_error = to_standard_error);
        }
    }, to_standard_error = to_standard_error);
}

PROGRAM_LOG_FLAGS_COLOR :: Console_Color.[
    .BLACK,    // None
    .WHITE,    // Info
    COLOR_WARNING,
    COLOR_ERROR,
    COLOR_DEBUG,
    COLOR_TRACE,
    .GREEN,    // TODO
];

COLOR_TRACE   :: Console_Color.CYAN;
COLOR_DEBUG   :: Console_Color.MAGENTA;
COLOR_ERROR   :: Console_Color.RED;
COLOR_WARNING :: Console_Color.YELLOW;

#import "Print_Color"()(USE_ANSI_CODES_ON_WINDOWS = false);
#if OS != .WINDOWS  POSIX :: #import "POSIX";

#scope_export

//
// Logger UI
//

app_logger_panel_ui :: () { using ImGui; using logger;
  if !app.show_logger_panel then return;

  push_allocator(temp);

  push_imgui_window("Event Log", p_open=*app.show_logger_panel);

  // Held for the whole draw: the rows point into the ring's entries, which the writer frees as it
  // overwrites them. Only the writer waits on it, never a thread that logs.
  lock(*ring_mutex);
  log_count := count(ring);
  if dropped  Text("Log count: % (% older dropped; see the log file)", log_count, dropped);
  else        Text("Log count: %", log_count);
  ButtonTooltip(tprint("Keeps the newest %; event_log_capacity under [logging] in settings.config.", ring.allocated));
  SameLine();
  Checkbox("Show info logs##logger", *logger.show_general);
  SameLine();
  Checkbox("Show warnings##logger", *logger.show_warnings);
  SameLine();
  if Button("Clear##logger") {
    atomic_store(*clear_requested, true);
    logger_wake_writer();
  }

  text_filter.Draw(*text_filter, "Filter##logger", -100.0);

  // Newest first.
  visible: [..] *Log_Message;
  for < i: 0..log_count-1 {
    message := ring[i];
    if !show_general && message.level == .General   continue;
    if !show_warnings && message.level == .Warning  continue;
    if !text_filter.PassFilter(*text_filter, message.message)  continue;
    array_add(*visible, message);
  }

  // Copied once ring_mutex is released, since copying logs.
  copy_text: string;

  if BeginChild("scrolling##logger", .{0, 0}, .None, .HorizontalScrollbar) {
    PushStyleVar(.ItemSpacing, .{0, 0}); defer PopStyleVar(); // .ItemSpacing

    flags: TableFlags = .RowBg | .Resizable;
    table_size := Vector2.{GetWindowWidth(), -1};

    if BeginTable("Event log##logger", 4, flags, table_size) {
        defer EndTable();
      TableSetupColumn("Timestamp");
      TableSetupColumn("Thread");
      TableSetupColumn("Level");
      TableSetupColumn("Message");

      TableHeadersRow();

      clipper: ListClipper;
      clipper.Constructor(*clipper); defer clipper.Destructor(*clipper);
      clipper.Begin(*clipper, xx visible.count);

      while clipper.Step(*clipper) {
        for row: clipper.DisplayStart..clipper.DisplayEnd-1 {
          message := visible[row];

          TableNextRow();

          log_color := get_color(message.level);
          PushStyleColor(.Text, log_color);

          TableSetColumnIndex(0);

          selectable_label := tprint("##sel%\0", row);
          selectable_flags: SelectableFlags = .SpanAllColumns | .AllowDoubleClick;
          if Selectable(selectable_label.data, false, selectable_flags) {
            if IsMouseDoubleClicked(0) {
              copy_text = tprint("[%, %, %] %",
                format_log_timestamp(message.timestamp),
                log_thread_label(message),
                message.level,
                message.message);
            }
          }

          SameLine();
          Text("%", format_log_timestamp(message.timestamp));

          TableSetColumnIndex(1);
          Text("%", log_thread_label(message));

          TableSetColumnIndex(2);
          Text("%", message.level);

          TableSetColumnIndex(3);
          Text("%", message.message);

          PopStyleColor(1); // Text: log_color
        }
      }
    }
  }
  EndChild();
  unlock(*ring_mutex);

  if copy_text {
    clipboard_set_text(copy_text);
    toast_show(.Success, "Copied log line");
  }
}

calendar_to_log_timestamp :: (using ct: Calendar_Time) -> string {
    date_part :: #bake_arguments formatInt(minimum_digits = 2);
    time_string := sprint("%-%-% %:%:%", year, date_part(month_starting_at_0 + 1), date_part(day_of_month_starting_at_0 + 1), date_part(hour), date_part(minute), date_part(second));
    return time_string;
}

format_log_timestamp :: (at: Apollo_Time) -> string {
    current_time := to_calendar(at, time_zone=.LOCAL);
    return calendar_to_log_timestamp(current_time);
}