instrument_log.c File Reference

Go to the source code of this file.

Data Structures
struct	asciichat_instr_only_selector
	Selector for filtering instrumentation output by file, function, or module. More...
struct	asciichat_instr_only_list
	Dynamic array of instrumentation selectors for filtering output. More...
struct	asciichat_instr_runtime
	Per-thread instrumentation runtime state. More...

Macros
#define	ASCII_INSTR_SOURCE_PRINT_HAVE_REGEX   1
#define	posix_write   write
#define	ASCII_INSTR_SOURCE_PRINT_DEFAULT_BASENAME   "ascii-instr"
#define	ASCII_INSTR_SOURCE_PRINT_MAX_LINE   4096
#define	ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET   2048

Typedefs
typedef enum asciichat_instr_selector_type	asciichat_instr_selector_type_t
typedef struct asciichat_instr_only_selector	asciichat_instr_only_selector_t
	Selector for filtering instrumentation output by file, function, or module.
typedef struct asciichat_instr_only_list	asciichat_instr_only_list_t
	Dynamic array of instrumentation selectors for filtering output.
typedef struct asciichat_instr_runtime	asciichat_instr_runtime_t
	Per-thread instrumentation runtime state.

Enumerations
enum	asciichat_instr_selector_type { ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_SUBSTRING = 0 , ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_GLOB = 1 , ASCII_INSTR_SOURCE_PRINT_SELECTOR_FUNCTION_GLOB = 2 , ASCII_INSTR_SOURCE_PRINT_SELECTOR_MODULE = 3 }

Functions
asciichat_instr_runtime_t *	asciichat_instr_runtime_get (void)
void	asciichat_instr_runtime_destroy (asciichat_instr_runtime_t *runtime)
void	asciichat_instr_runtime_global_destroy (void)
void	asciichat_instr_log_line (const char *file_path, uint32_t line_number, const char *function_name, const char *snippet, uint8_t is_macro_expansion)
bool	asciichat_instr_coverage_enabled (void)
void	asciichat_instr_log_pc (uintptr_t program_counter)

Macro Definition Documentation

ASCII_INSTR_SOURCE_PRINT_DEFAULT_BASENAME

#define ASCII_INSTR_SOURCE_PRINT_DEFAULT_BASENAME   "ascii-instr"

Definition at line 56 of file instrument_log.c.

ASCII_INSTR_SOURCE_PRINT_HAVE_REGEX

#define ASCII_INSTR_SOURCE_PRINT_HAVE_REGEX   1

Definition at line 33 of file instrument_log.c.

ASCII_INSTR_SOURCE_PRINT_MAX_LINE

#define ASCII_INSTR_SOURCE_PRINT_MAX_LINE   4096

Definition at line 60 of file instrument_log.c.

ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET

#define ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET   2048

Definition at line 64 of file instrument_log.c.

posix_write

#define posix_write   write

Definition at line 52 of file instrument_log.c.

Typedef Documentation

asciichat_instr_only_list_t

typedef struct asciichat_instr_only_list asciichat_instr_only_list_t

Dynamic array of instrumentation selectors for filtering output.

asciichat_instr_only_selector_t

typedef struct asciichat_instr_only_selector asciichat_instr_only_selector_t

Selector for filtering instrumentation output by file, function, or module.

asciichat_instr_runtime_t

typedef struct asciichat_instr_runtime asciichat_instr_runtime_t

Per-thread instrumentation runtime state.

Tracks state for source code instrumentation logging, including file descriptors, filter configuration, and rate limiting for the current thread.

asciichat_instr_selector_type_t

typedef enum asciichat_instr_selector_type asciichat_instr_selector_type_t

Enumeration Type Documentation

asciichat_instr_selector_type

enum asciichat_instr_selector_type

Enumerator
ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_SUBSTRING
ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_GLOB
ASCII_INSTR_SOURCE_PRINT_SELECTOR_FUNCTION_GLOB
ASCII_INSTR_SOURCE_PRINT_SELECTOR_MODULE

Definition at line 67 of file instrument_log.c.

                                           {
  ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_SUBSTRING = 0,
  ASCII_INSTR_SOURCE_PRINT_SELECTOR_FILE_GLOB = 1,
  ASCII_INSTR_SOURCE_PRINT_SELECTOR_FUNCTION_GLOB = 2,
  ASCII_INSTR_SOURCE_PRINT_SELECTOR_MODULE = 3,
} asciichat_instr_selector_type_t;

Function Documentation

asciichat_instr_coverage_enabled()

bool asciichat_instr_coverage_enabled

(

void

)

Definition at line 434 of file instrument_log.c.

                                            {
  if (g_disable_write) {
    return false;
  }
 
  // Initialize runtime once using mutex-protected initialization
  if (!g_runtime_initialized) {
    if (!g_runtime_mutex_initialized) {
      mutex_init(&g_runtime_mutex);
      g_runtime_mutex_initialized = true;
    }
 
    mutex_lock(&g_runtime_mutex);
    if (!g_runtime_initialized) {
      asciichat_instr_runtime_init_once();
    }
    mutex_unlock(&g_runtime_mutex);
  }
 
  return g_coverage_enabled;
}

References mutex_init().

Referenced by asciichat_instr_log_pc().

asciichat_instr_log_line()

void asciichat_instr_log_line	(	const char *	file_path,
		uint32_t	line_number,
		const char *	function_name,
		const char *	snippet,
		uint8_t	is_macro_expansion
	)

Definition at line 284 of file instrument_log.c.

                                                                               {
  // Instrumentation is enabled by default when the binary is built with Source Print.
  // Set ASCII_INSTR_SOURCE_PRINT_ENABLE=0 to disable tracing at runtime.
  if (!g_instrumentation_enabled_checked) {
    const char *enable_env = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_ENABLE");
    // Default to enabled (true) - only disable if explicitly set to "0", "false", "off", or "no"
    if (enable_env != NULL && enable_env[0] != '\0') {
      g_instrumentation_enabled = asciichat_instr_env_is_enabled(enable_env);
    } else {
      g_instrumentation_enabled = true; // Default to enabled when instrumented
    }
    g_instrumentation_enabled_checked = true;
  }
 
  if (!g_instrumentation_enabled) {
    return;
  }
 
  if (g_disable_write) {
    return;
  }
 
  if (g_logging_reentry_guard) {
    return;
  }
 
  g_logging_reentry_guard = true;
 
  asciichat_instr_runtime_t *runtime = asciichat_instr_runtime_get();
  if (runtime == NULL) {
    goto cleanup;
  }
 
  if (!asciichat_instr_should_log(runtime, file_path, line_number, function_name)) {
    goto cleanup;
  }
 
  runtime->call_counter++;
  if (runtime->rate_enabled) {
    const uint64_t counter = runtime->call_counter;
    if (((counter - 1U) % runtime->rate) != 0U) {
      goto cleanup;
    }
  }
 
  if (runtime->fd < 0) {
    if (asciichat_instr_open_log_file(runtime) != 0) {
      runtime->stderr_fallback = true;
    }
  }
 
  const int fd = runtime->stderr_fallback ? STDERR_FILENO : runtime->fd;
  char buffer[ASCII_INSTR_SOURCE_PRINT_MAX_LINE];
  size_t pos = 0;
 
  uint64_t realtime_ns = time_get_realtime_ns();
  time_t sec = (time_t)(realtime_ns / NS_PER_SEC_INT);
  long nsec = (long)(realtime_ns % NS_PER_SEC_INT);
  struct tm tm_now;
  memset(&tm_now, 0, sizeof(tm_now));
  if (platform_gtime(&sec, &tm_now) != ASCIICHAT_OK) {
    memset(&tm_now, 0, sizeof(tm_now));
  }
 
  char timestamp[32];
  size_t ts_len = strftime(timestamp, sizeof(timestamp), "%Y-%m-%dT%H:%M:%S", &tm_now);
  if (ts_len == 0) {
    SAFE_STRNCPY(timestamp, "1970-01-01T00:00:00", sizeof(timestamp));
    ts_len = strlen(timestamp);
  }
 
  char elapsed_buf[32];
  elapsed_buf[0] = '\0';
  if (g_ticks_initialized) {
    uint64_t now_ns = time_get_ns();
    uint64_t elapsed_ns = time_elapsed_ns(g_start_ns, now_ns);
    if (format_duration_ns((double)elapsed_ns, elapsed_buf, sizeof(elapsed_buf)) < 0) {
      elapsed_buf[0] = '\0';
    }
  }
 
  runtime->sequence++;
 
  const char *elapsed_field = (elapsed_buf[0] != '\0') ? elapsed_buf : "-";
 
  const char *safe_file_path = (file_path != NULL) ? file_path : "<unknown>";
  pos += safe_snprintf(buffer + pos, sizeof(buffer) - pos,
                       "pid=%d tid=%llu seq=%llu ts=%.*s.%09ldZ elapsed=%s file=%s line=%u func=%s macro=%u snippet=",
                       runtime->pid, (unsigned long long)runtime->thread_id, (unsigned long long)runtime->sequence,
                       (int)ts_len, timestamp, nsec, elapsed_field, safe_file_path, line_number,
                       function_name ? function_name : "<unknown>", (unsigned)is_macro_expansion);
 
  if (snippet != NULL) {
    size_t snippet_len = strnlen(snippet, ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET);
    for (size_t i = 0; i < snippet_len && pos < sizeof(buffer) - 2; ++i) {
      const char ch = snippet[i];
      switch (ch) {
      case '\n':
        buffer[pos++] = '\\';
        buffer[pos++] = 'n';
        break;
      case '\r':
        buffer[pos++] = '\\';
        buffer[pos++] = 'r';
        break;
      case '\t':
        buffer[pos++] = '\\';
        buffer[pos++] = 't';
        break;
      default:
        buffer[pos++] = ch;
        break;
      }
    }
  }
 
  if (pos >= sizeof(buffer) - 1) {
    pos = sizeof(buffer) - 2;
  }
 
  buffer[pos++] = '\n';
  buffer[pos] = '\0';
 
  asciichat_instr_write_full(fd, buffer, pos);
 
  // Also echo to stderr if requested via environment variable
  if (!g_echo_to_stderr_initialized) {
    const char *echo_env = SAFE_GETENV("ASCII_CHAT_DEBUG_SELF_SOURCE_CODE_LOG_STDERR");
    g_echo_to_stderr = asciichat_instr_env_is_enabled(echo_env);
    g_echo_to_stderr_initialized = true;
  }
 
  if (g_echo_to_stderr && !runtime->stderr_fallback) {
    // Write to stderr in addition to the log file
    // Suppress Windows deprecation warning for POSIX write function
#ifdef _WIN32
#pragma clang diagnostic push
#pragma clang diagnostic ignored "-Wdeprecated-declarations"
#endif
    (void)posix_write(STDERR_FILENO, buffer, pos);
#ifdef _WIN32
#pragma clang diagnostic pop
#endif
  }
 
cleanup:
  g_logging_reentry_guard = false;
}

References ASCII_INSTR_SOURCE_PRINT_MAX_LINE, ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET, asciichat_instr_runtime_get(), asciichat_instr_runtime::call_counter, asciichat_instr_runtime::fd, file_path, format_duration_ns(), asciichat_instr_runtime::pid, posix_write, asciichat_instr_runtime::rate, asciichat_instr_runtime::rate_enabled, safe_snprintf(), asciichat_instr_runtime::sequence, asciichat_instr_runtime::stderr_fallback, asciichat_instr_runtime::thread_id, time_elapsed_ns(), time_get_ns(), and time_get_realtime_ns().

Referenced by asciichat_instr_log_pc().

asciichat_instr_log_pc()

void asciichat_instr_log_pc

(

uintptr_t

program_counter

)

Definition at line 456 of file instrument_log.c.

                                                       {
  if (!asciichat_instr_coverage_enabled()) {
    return;
  }
 
  char snippet[64];
  safe_snprintf(snippet, sizeof(snippet), "pc=0x%zx", (size_t)program_counter);
  asciichat_instr_log_line("__coverage__", 0, "<coverage>", snippet, ASCII_INSTR_SOURCE_PRINT_MACRO_NONE);
}

References asciichat_instr_coverage_enabled(), asciichat_instr_log_line(), and safe_snprintf().

Referenced by __sanitizer_cov_trace_pc_guard().

asciichat_instr_runtime_destroy()

void asciichat_instr_runtime_destroy

(

asciichat_instr_runtime_t *

runtime

)

Definition at line 221 of file instrument_log.c.

                                                                         {
  if (runtime == NULL) {
    return;
  }
 
  if (runtime->fd >= 0) {
    platform_close(runtime->fd);
    runtime->fd = -1;
  }
 
#if ASCII_INSTR_SOURCE_PRINT_HAVE_REGEX
  if (runtime->include_regex_valid) {
    regfree(&runtime->include_regex);
    runtime->include_regex_valid = false;
  }
  if (runtime->exclude_regex_valid) {
    regfree(&runtime->exclude_regex);
    runtime->exclude_regex_valid = false;
  }
  if (runtime->function_include_regex_valid) {
    regfree(&runtime->function_include_regex);
    runtime->function_include_regex_valid = false;
  }
  if (runtime->function_exclude_regex_valid) {
    regfree(&runtime->function_exclude_regex);
    runtime->function_exclude_regex_valid = false;
  }
#endif
 
  asciichat_instr_only_list_destroy(&runtime->only_selectors);
  SAFE_FREE(runtime);
}

References asciichat_instr_runtime::exclude_regex, asciichat_instr_runtime::exclude_regex_valid, asciichat_instr_runtime::fd, asciichat_instr_runtime::function_exclude_regex, asciichat_instr_runtime::function_exclude_regex_valid, asciichat_instr_runtime::function_include_regex, asciichat_instr_runtime::function_include_regex_valid, asciichat_instr_runtime::include_regex, asciichat_instr_runtime::include_regex_valid, asciichat_instr_runtime::only_selectors, and platform_close().

asciichat_instr_runtime_get()

asciichat_instr_runtime_t * asciichat_instr_runtime_get

(

void

)

Definition at line 167 of file instrument_log.c.

                                                             {
  if (g_disable_write) {
    return NULL;
  }
 
  // Initialize runtime once using mutex-protected initialization
  if (!g_runtime_initialized) {
    // Initialize mutex if needed
    if (!g_runtime_mutex_initialized) {
      mutex_init(&g_runtime_mutex);
      g_runtime_mutex_initialized = true;
    }
 
    mutex_lock(&g_runtime_mutex);
    if (!g_runtime_initialized) {
      asciichat_instr_runtime_init_once();
    }
    mutex_unlock(&g_runtime_mutex);
  }
 
  asciichat_instr_runtime_t *runtime = ascii_tls_get(g_runtime_key);
  if (runtime != NULL) {
    return runtime;
  }
 
  runtime = SAFE_CALLOC(1, sizeof(*runtime), asciichat_instr_runtime_t *);
  if (runtime == NULL) {
    return NULL;
  }
 
  runtime->pid = platform_get_pid();
  runtime->thread_id = asciichat_thread_current_id();
  runtime->sequence = 0;
  runtime->call_counter = 0;
  runtime->fd = -1;
  runtime->filter_include = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_INCLUDE");
  runtime->filter_exclude = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_EXCLUDE");
  runtime->filter_thread = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_THREAD");
  runtime->filter_function_include = NULL;
  runtime->filter_function_exclude = NULL;
  runtime->filters_enabled = false;
  runtime->rate = 1;
  runtime->rate_enabled = false;
 
  asciichat_instr_runtime_configure(runtime);
 
  if (ascii_tls_set(g_runtime_key, runtime) != 0) {
    SAFE_FREE(runtime);
    return NULL;
  }
 
  return runtime;
}

References ascii_tls_get(), ascii_tls_set(), asciichat_thread_current_id(), asciichat_instr_runtime::call_counter, asciichat_instr_runtime::fd, asciichat_instr_runtime::filter_exclude, asciichat_instr_runtime::filter_function_exclude, asciichat_instr_runtime::filter_function_include, asciichat_instr_runtime::filter_include, asciichat_instr_runtime::filter_thread, asciichat_instr_runtime::filters_enabled, mutex_init(), asciichat_instr_runtime::pid, platform_get_pid(), asciichat_instr_runtime::rate, asciichat_instr_runtime::rate_enabled, asciichat_instr_runtime::sequence, and asciichat_instr_runtime::thread_id.

Referenced by asciichat_instr_log_line().

asciichat_instr_runtime_global_destroy()

void asciichat_instr_runtime_global_destroy

(

void

)

Definition at line 254 of file instrument_log.c.

                                                  {
  if (g_runtime_mutex_initialized) {
    mutex_lock(&g_runtime_mutex);
  }
 
  if (g_runtime_initialized) {
    g_disable_write = true;
    ascii_tls_key_delete(g_runtime_key);
    g_runtime_initialized = false;
    g_ticks_initialized = false;
    g_start_ns = 0;
    g_coverage_enabled = false;
    g_output_dir_set = false;
    g_output_dir[0] = '\0';
    g_instrumentation_enabled_checked = false;
    g_instrumentation_enabled = false;
    g_echo_to_stderr_initialized = false;
    g_echo_to_stderr = false;
  }
 
  // Reset g_disable_write so instrumentation can be re-enabled in subsequent tests
  g_disable_write = false;
 
  if (g_runtime_mutex_initialized) {
    mutex_unlock(&g_runtime_mutex);
    mutex_destroy(&g_runtime_mutex);
    g_runtime_mutex_initialized = false;
  }
}

References ascii_tls_key_delete(), and mutex_destroy().