src/common/session/render.c

Go to the documentation of this file.

#include <ascii-chat/otel.h>
 
#include <ascii-chat/tui/input.h>
#include <ascii-chat/tui/controller.h>
#include "session/render.h"
#include "session/capture.h"
#include "session/display.h"
#include "session/pipeline.h"
#include <ascii-chat/terminal/fd/reader.h>
#include <ascii-chat/tui/keyboard_help.h>
#include <ascii-chat/tui/splash.h>
#include <ascii-chat/log/search.h>
#include <ascii-chat/common.h>
#include <fcntl.h>
#include <unistd.h>
#include <ascii-chat/log/log.h>
#include <ascii-chat/options/options.h>
#include <ascii-chat/util/time.h>
#include <ascii-chat/audio/audio.h>
#include <ascii-chat/media/source.h>
#include <ascii-chat/media/ffmpeg_decoder.h>
#include <ascii-chat/os/keyboard.h>
#include <libplatform/terminal.h>
#include <libplatform/compiler.h>
#include <libplatform/system.h>
#include <libplatform/terminal.h>
#include <ascii-chat/asciichat_errno.h>
#include <ascii-chat/app_callbacks.h>
 
#include <stddef.h>
#include <stdbool.h>
#include <stdio.h>
#include <inttypes.h>
#ifndef _WIN32
#include <unistd.h>
#endif
 
/* ============================================================================
 * Unified Render Loop Implementation
 * ============================================================================ */
 
// Global flags for snapshot mode timing
bool g_snapshot_first_frame_rendered = false;
uint64_t g_snapshot_first_frame_rendered_ns = 0; // Timestamp when first frame was rendered (for terminal output)
uint64_t g_snapshot_first_capture_ns = 0;        // Timestamp when first frame was captured (for video output)
uint64_t g_snapshot_actual_duration_ms = 0;      // Actual elapsed time in ms when capture thread hits snapshot timeout
uint64_t g_snapshot_last_capture_elapsed_ns = 0; // Elapsed time from first to last frame capture (for PTS distribution)
 
asciichat_error_t session_render_loop(session_capture_ctx_t *capture, session_display_ctx_t *display,
                                      session_should_exit_fn should_exit, session_capture_fn capture_cb,
                                      session_sleep_for_frame_fn sleep_cb, session_keyboard_handler_fn keyboard_handler,
                                      void *user_data) {
  // Validate required parameters
  log_debug("capture=%p, display=%p, mode=%s", (void *)capture, (void *)display,
            capture ? "SYNCHRONOUS" : "EVENT-DRIVEN");
 
  if (!display) {
    SET_ERRNO(ERROR_INVALID_PARAM, "display context is NULL");
    return ERROR_INVALID_PARAM;
  }
 
  if (!should_exit) {
    SET_ERRNO(ERROR_INVALID_PARAM, "should_exit callback is NULL");
    return ERROR_INVALID_PARAM;
  }
 
  // Validate mode: either capture context OR custom callbacks, not both
  if (!capture && !capture_cb) {
    SET_ERRNO(ERROR_INVALID_PARAM, "must provide either capture context or capture callback");
    return ERROR_INVALID_PARAM;
  }
 
  if (capture && capture_cb) {
    SET_ERRNO(ERROR_INVALID_PARAM, "cannot provide both capture context and capture callback");
    return ERROR_INVALID_PARAM;
  }
 
  // In event-driven mode, both capture_cb and sleep_cb must be provided together
  if (capture_cb && !sleep_cb) {
    SET_ERRNO(ERROR_INVALID_PARAM, "capture_cb requires sleep_cb (must provide both or neither)");
    return ERROR_INVALID_PARAM;
  }
 
  if (sleep_cb && !capture_cb) {
    SET_ERRNO(ERROR_INVALID_PARAM, "sleep_cb requires capture_cb (must provide both or neither)");
    return ERROR_INVALID_PARAM;
  }
 
  // SYNCHRONOUS MODE: Use threaded pipeline for capture + render
  if (capture != NULL) {
    log_debug("[SESSION_RENDER_LOOP_SYNCHRONOUS] Creating pipeline... (capture=%p, display=%p)", (void *)capture,
              (void *)display);
    session_pipeline_t *pipeline = NULL;
    asciichat_error_t pipeline_err = session_pipeline_create(capture, display, &pipeline);
    log_debug("[SESSION_RENDER_LOOP_SYNCHRONOUS] pipeline_create returned: %d (pipeline=%p)", pipeline_err,
              (void *)pipeline);
    if (pipeline_err != ASCIICHAT_OK) {
      log_error("[SESSION_RENDER_LOOP_SYNCHRONOUS] Pipeline creation failed %s",
                asciichat_error_format(NULL, pipeline_err));
      return pipeline_err;
    }
    log_debug("[SESSION_RENDER_LOOP_SYNCHRONOUS] Pipeline created successfully, running main loop...");
 
    // Disable logging to stdout/stderr during rendering (same as event-driven mode).
    // This prevents logs from mixing with ASCII art output. Logs still go to file.
    log_set_terminal_output(false);
    asciichat_error_t run_err = session_pipeline_run_main(pipeline, should_exit, keyboard_handler, user_data);
    log_set_terminal_output(true);
 
    asciichat_error_t drain_err = session_pipeline_destroy(pipeline);
    // The encoder no longer writes here. Use capture duration, excluding time spent draining.
    if (GET_OPTION(snapshot_mode) && display && g_snapshot_first_capture_ns > 0)
      session_display_set_snapshot_actual_duration(display, (double)g_snapshot_actual_duration_ms / 1000.0);
 
    return run_err == ASCIICHAT_OK ? drain_err : run_err;
  } else {
    log_warn("capture is NULL - will not use pipeline (capture_cb=%p)", (void *)capture_cb);
  }
 
  // Snapshot mode state tracking
  bool snapshot_mode = GET_OPTION(snapshot_mode);
  bool snapshot_done = false;
  uint64_t frames_rendered_since_first = 0; // Track frames rendered after first frame (for snapshot delay)
  // NOTE: g_snapshot_first_frame_rendered is set by display.c when first frame is rendered via platform_write_all()
 
  log_debug("display=%p capture=%p capture_cb=%p snapshot_mode=%s snapshot_delay=%.2f", (void *)display,
            (void *)capture, (void *)capture_cb, snapshot_mode ? "YES" : "NO",
            snapshot_mode ? GET_OPTION(snapshot_delay) : 0.0);
  if (should_exit(user_data)) {
    log_warn("EXIT signal already set at entry, aborting render loop");
    return ASCIICHAT_OK;
  }
 
  // Keyboard input initialization (if keyboard handler is provided)
  // Disable keyboard only in snapshot mode
  // Keyboard is pre-initialized from asciichat_shared_init()
  // Allow keyboard input in all other modes if handler provided
  bool keyboard_enabled = keyboard_handler && !snapshot_mode;
 
  // Pause mode state tracking (for pause/unpause transitions in event-driven mode)
  bool initial_paused_frame_rendered = false;
  bool is_paused = false;
  log_debug("Keyboard setup - handler=%p snapshot=%s enabled=%s", (void *)keyboard_handler,
            snapshot_mode ? "YES" : "NO", keyboard_enabled ? "YES" : "NO");
 
  // Log TTY detection status for debugging keyboard issues
  log_debug("TTY Status: stdin_tty=%d stdout_tty=%d interactive=%d keyboard_enabled=%d", terminal_is_stdin_tty(),
            terminal_is_stdout_tty(), terminal_is_interactive(), keyboard_enabled);
 
  // Frame rate timing (event-driven mode only)
  uint64_t frame_count = 0;
  uint64_t frame_start_ns = 0;
 
  // Event-driven mode: disable console logging during rendering to prevent logs from corrupting frame display
  // This must be done BEFORE the render loop to avoid repeated lock/unlock cycles that could cause deadlocks
  log_debug("[EVENT_DRIVEN_MODE] Entering render loop. snapshot_mode=%s", snapshot_mode ? "YES" : "NO");
  log_set_terminal_output(false);
 
  asciichat_error_t capture_result = ASCIICHAT_OK;
  // Main render loop
  int loop_iteration = 0;
  log_debug("[RENDER_LOOP_START] snapshot_mode=%s, snapshot_delay=%.2f", snapshot_mode ? "YES" : "NO",
            snapshot_mode ? GET_OPTION(snapshot_delay) : 0.0);
 
  // Wait for splash animation to complete before rendering first frame
  // This prevents ASCII art from mixing with splash screen output
  // But skip for immediate snapshots (snapshot-delay=0) which need to output first frame immediately
  static bool splash_wait_done = false;
  if (!splash_wait_done) {
    splash_wait_done = true;
    if (!(GET_OPTION(snapshot_mode) && GET_OPTION(snapshot_delay) == 0.0)) {
      // Re-enable logging briefly for splash wait, then disable again
      log_set_terminal_output(true);
      splash_wait_for_animation();
      log_set_terminal_output(false);
    }
  }
 
  // In snapshot mode, we must render at least one frame before checking should_exit
  // to ensure the snapshot delay timer can start
  bool force_first_iteration = snapshot_mode && frame_count == 0;
 
  // Register display context globally so signal handlers (Ctrl+C) can access it
  // This enables Ctrl+C to close the help screen instead of quitting when help is active
  session_display_set_global_context(display);
 
  while (force_first_iteration || (!should_exit(user_data) && !(snapshot_mode && snapshot_done))) {
    force_first_iteration = false;
    loop_iteration++;
    log_debug("[LOOP_ITER] iteration=%d, snapshot_done=%s, frame_count=%lu", loop_iteration,
              snapshot_done ? "YES" : "NO", frame_count);
    if (loop_iteration % 60 == 0) {
      log_debug("iteration %d, should_exit check returning false", loop_iteration);
    }
    // Snapshot mode: exit at start of iteration if done
    // This prevents frame 2+ from being captured when snapshot_delay has elapsed
    if (snapshot_mode && snapshot_done && frame_count > 0) {
      log_debug("[SNAPSHOT_EXIT] Snapshot mode: exiting at loop iteration start (snapshot_done=true, frames=%lu)",
                frame_count);
      break;
    }
 
    log_debug_every(US_PER_SEC_INT, "frame %lu", frame_count);
    // Frame timing - measure total time to maintain target FPS
    frame_start_ns = time_get_ns();
 
    // Frame capture and timing - mode-dependent
    image_t *image = NULL;
    uint64_t capture_start_ns = 0;
    uint64_t capture_end_ns = 0;
    uint64_t pre_convert_ns = 0;
    uint64_t post_convert_ns = 0;
    uint64_t conversion_elapsed_ns = 0;
 
    // EVENT-DRIVEN MODE: Frames come from callbacks
    // Both sleep_cb and capture_cb are guaranteed non-NULL by validation above
    sleep_cb(user_data);
    ASCII_OTEL_SCOPE(PIPELINE_DISPLAY);
    asciichat_errno_scope_t frame_scope = errno_checkpoint();
    image = capture_cb(user_data);
 
    if (!image) {
      asciichat_error_context_t failure;
      if (errno_peek_since(frame_scope, &failure)) {
        capture_result = failure.code;
        break;
      }
      // No frame available - this is normal in async modes (network latency, etc.)
      // Just continue to next iteration, don't exit
      continue;
    }
 
    // Event-driven mode: increment frame count
    frame_count++;
 
    // Convert image to ASCII using display context
    // Handles all palette, terminal caps, width, height, stretch settings
    pre_convert_ns = time_get_ns();
    char *ascii_frame = session_display_convert_to_ascii_reuse(display, image);
    post_convert_ns = time_get_ns();
    conversion_elapsed_ns = post_convert_ns - pre_convert_ns;
 
    if (frame_count <= 3) {
      log_debug("RENDER_LOOP[%lu]: image=%p, ascii_frame=%p (conversion took %u ms)", frame_count, (void *)image,
                (void *)ascii_frame, (unsigned)(conversion_elapsed_ns / NS_PER_MS_INT));
    }
 
    // Declare variables that need scope beyond the if (ascii_frame) block
    bool is_paused_frame = initial_paused_frame_rendered && is_paused;
    bool output_paused_frame = snapshot_mode && is_paused_frame;
    uint64_t pre_render_ns = 0, post_render_ns = 0;
 
    if (ascii_frame) {
      log_debug_every(US_PER_SEC_INT, "ascii_frame ready (len=%zu)", strlen(ascii_frame));
 
      // Always attempt to render frames; the display context will handle filtering based on:
      // - TTY mode: render all frames with cursor control (even in snapshot mode, for animation)
      // - Piped mode: render all frames without cursor control (for continuous capture)
      // - Snapshot mode on non-TTY: only the display context renders the final frame
      // BUT: don't render if splash screen is still animating - wait for it to finish
      bool splash_running = splash_is_running();
      bool should_write = !splash_running;
      if (frame_count == 1) {
        log_dev("[RENDER_FRAME] Frame 1: splash_is_running=%s, should_write=%s", splash_running ? "YES" : "NO",
                should_write ? "YES" : "NO");
      }
      if (should_write) {
        // is_final = true when: snapshot done, or paused frame (for both snapshot and pause modes)
        // Profile: render frame
        pre_render_ns = time_get_ns();
 
        if (frame_count <= 5 || frame_count % 10 == 0) {
          log_debug("Frame %lu - calling session_display_render_frame, display=%p", (unsigned long)frame_count,
                    (void *)display);
        }
 
        // Check if SIGINT handler cancelled help mode (Ctrl+C while help is open).
        // The signal handler sets an atomic flag instead of touching state directly.
        if (display && keyboard_help_check_signal_cancel()) {
          keyboard_help_toggle(display);
          log_debug("Ctrl+C cancelled help screen - returning to ASCII art");
        }
 
        session_display_render_frame(display, ascii_frame);
 
        // Snapshot mode: increment frame counter for all displayed frames
        // Counter starts at 1 for the first displayed frame, then 2, 3, 4... for subsequent frames
        // Timer is started by display.c when g_snapshot_first_frame_rendered is set
        if (snapshot_mode && g_snapshot_first_frame_rendered) {
          frames_rendered_since_first++;
          log_debug_every(US_PER_SEC_INT, "[SNAPSHOT] Frame rendered: frames_rendered_since_first=%lu",
                          frames_rendered_since_first);
        }
      }
 
      // Keyboard input polling (if enabled) - MUST come before snapshot exit check so help screen can be toggled
      // Allow keyboard in snapshot mode too (for help screen toggle debugging)
      // Only enable keyboard if BOTH stdin AND stdout are TTYs to avoid buffering issues
      // when tcsetattr() modifies the tty line discipline
      if (keyboard_enabled && keyboard_handler) {
        uint64_t keyboard_start_ns = time_get_ns();
        keyboard_key_t key = ui_input_read_key(UI_SCREEN_MEDIA);
        double keyboard_elapsed_ns = (double)time_elapsed_ns(keyboard_start_ns, time_get_ns());
        if (keyboard_elapsed_ns >= 0.0) {
          char _duration_str[TIME_DURATION_BUFFER_SIZE];
          time_pretty((uint64_t)keyboard_elapsed_ns, -1, _duration_str, sizeof(_duration_str));
          log_dev_every(1 * NS_PER_SEC_INT, "RENDER[%lu] Keyboard read complete (key=%d) in %s",
                        (unsigned long)frame_count, key, _duration_str);
        }
        if (key != KEY_NONE) {
          log_debug("KEYBOARD: Key pressed: code=%d char='%c'", key, (key >= 32 && key < 127) ? key : '?');
          // Normal keyboard handler
          log_debug("KEYBOARD: Normal handler taking key %d", key);
          keyboard_handler(capture, key, user_data);
        }
      }
 
      // Free frame before checking exit conditions to avoid double-free
      session_display_release_ascii(display, ascii_frame);
    }
 
    // Snapshot mode: check if elapsed time has reached snapshot_delay duration (terminal render timing)
    // Separate from capture timing - both should measure their own snapshot_delay
    if (snapshot_mode && !snapshot_done) {
      if (g_snapshot_first_frame_rendered && g_snapshot_first_frame_rendered_ns > 0) {
        double snapshot_delay = GET_OPTION(snapshot_delay);
        uint64_t now_ns = time_get_ns();
        uint64_t elapsed_ns = now_ns - g_snapshot_first_frame_rendered_ns;
        double elapsed_sec = (double)elapsed_ns / (double)NS_PER_SEC_INT;
 
        if (frames_rendered_since_first == 1 || frames_rendered_since_first % 20 == 0) {
          log_debug("SNAPSHOT: RENDER_CHECK iter=%lu elapsed=%.3f target=%.2f (from first_frame_rendered)",
                    frames_rendered_since_first, elapsed_sec, snapshot_delay);
        }
 
        // snapshot_delay=0 means exit after first frame
        // snapshot_delay>0 means wait that many seconds before exiting
        // Exit is based on elapsed wall-clock time, not frame count
        bool should_exit = (snapshot_delay == 0.0) || (elapsed_sec >= snapshot_delay);
 
        if (should_exit) {
          log_debug("SNAPSHOT: RENDER_DONE at iteration %lu - elapsed=%.3f target=%.2f (setting snapshot_done=true)",
                    frames_rendered_since_first, elapsed_sec, snapshot_delay);
          // We don't end frames with newlines so the next log would print on the same line as the frame's
          // last row without an \n here. We only need this \n in stdout when interactive,
          // so piped snapshots don't have a weird newline in stdout that they don't need.
          if (terminal_is_interactive()) {
            ui_controller_printf(STDOUT_FILENO, "\n");
          }
          snapshot_done = true;
        }
      } else {
        if (frames_rendered_since_first == 0) {
          log_debug("SNAPSHOT: Waiting for first_frame_rendered (g_snapshot_first_frame_rendered=%d, "
                    "g_snapshot_first_frame_rendered_ns=%llu)",
                    g_snapshot_first_frame_rendered, (unsigned long long)g_snapshot_first_frame_rendered_ns);
        }
      }
    }
 
    // Exit conditions: snapshot mode exits after capturing the final frame or initial paused frame
    if (snapshot_mode && (snapshot_done || output_paused_frame)) {
      log_debug("SNAPSHOT: EXIT CONDITION MET - snapshot_done=%d, output_paused_frame=%d", snapshot_done,
                output_paused_frame);
 
      // Calculate elapsed time from first frame captured (for video file)
      // This is separate from render time - video should span from first capture to last capture
      double capture_elapsed_sec = 0.0;
      if (g_snapshot_first_capture_ns > 0) {
        uint64_t now_ns = time_get_ns();
        uint64_t elapsed_ns = now_ns - g_snapshot_first_capture_ns;
        capture_elapsed_sec = (double)elapsed_ns / (double)NS_PER_SEC_INT;
        log_debug("SNAPSHOT: EXIT - Capture elapsed: %.3f seconds, render elapsed: %.3f seconds, "
                  "g_snapshot_first_capture_ns=%llu",
                  capture_elapsed_sec,
                  (g_snapshot_first_frame_rendered_ns > 0)
                      ? (double)(now_ns - g_snapshot_first_frame_rendered_ns) / NS_PER_SEC_INT
                      : 0.0,
                  (unsigned long long)g_snapshot_first_capture_ns);
      } else {
        log_warn("SNAPSHOT: EXIT condition met but g_snapshot_first_capture_ns is 0!");
      }
 
      // Pass actual capture elapsed time to encoder for correct video duration
      log_debug("SNAPSHOT: About to call session_display_set_snapshot_actual_duration with duration=%.3f, display=%p",
                capture_elapsed_sec, (void *)display);
      if (display) {
        session_display_set_snapshot_actual_duration(display, capture_elapsed_sec);
      } else {
        log_warn("SNAPSHOT: display context is NULL!");
      }
 
      // Signal application to exit in snapshot mode
      APP_CALLBACK_VOID(signal_exit);
      break;
    }
 
    // Frame rendering and timing details (moved down since snapshot exit is now above it)
    if (ascii_frame) {
 
      // Measure frame completion right after rendering, BEFORE keyboard polling
      // This gives us accurate timing for just the core frame operations
      uint64_t frame_end_render_ns = time_get_ns();
 
      // Calculate each phase duration
      uint64_t prestart_ms =
          (capture_start_ns > frame_start_ns) ? (capture_start_ns - frame_start_ns) / NS_PER_MS_INT : 0;
      uint64_t capture_ms =
          (capture_end_ns > capture_start_ns) ? (capture_end_ns - capture_start_ns) / NS_PER_MS_INT : 0;
      uint64_t convert_ms = conversion_elapsed_ns / NS_PER_MS_INT;
      uint64_t render_ms =
          (post_render_ns > pre_render_ns && post_render_ns > 0) ? (post_render_ns - pre_render_ns) / NS_PER_MS_INT : 0;
      uint64_t total_ms =
          (frame_end_render_ns > frame_start_ns) ? (frame_end_render_ns - frame_start_ns) / NS_PER_MS_INT : 0;
 
      // Log phase breakdown every 5 frames
      if (frame_count % 5 == 0) {
        log_dev_every(
            2 * NS_PER_SEC_INT,
            "PHASE_BREAKDOWN[%lu]: prestart=%llu ms, capture=%llu ms, convert=%llu ms, render=%llu ms (total=%llu ms)",
            frame_count, prestart_ms, capture_ms, convert_ms, render_ms, total_ms);
      }
    } else {
      // Snapshot mode: even if frame conversion failed, check if we should exit
      // This ensures snapshot_delay is honored even if display context isn't rendering
      if (snapshot_mode && snapshot_done) {
        break;
      }
    }
 
    // In event-driven mode, frame rate limiting is handled by the sleep_cb callback
    // Synchronous mode (with capture context) uses the pipeline and returns early above
 
    // Note: Images returned by media sources are cached/reused and should NOT be destroyed
    // The image pointers are managed by the source and will be cleaned up on source shutdown
  } // while (!should_exit(user_data)) {
 
  // Re-enable console logging after rendering completes
  log_set_terminal_output(true);
  if (!snapshot_mode && terminal_is_interactive()) {
    ui_controller_printf(STDOUT_FILENO, "\n");
  }
 
  // Keyboard input cleanup (if it was initialized)
  if (keyboard_enabled) {
    ui_controller_remove(UI_SCREEN_HELP);
    ui_controller_remove(UI_SCREEN_MEDIA);
    log_debug_every(2 * NS_PER_SEC_INT, "Keyboard input disabled");
  }
 
  // Unregister global display context (for signal handlers)
  session_display_set_global_context(NULL);
 
  return capture_result;
}