Add richer logging for paste and event tracing

This commit is contained in:
Ahmed Ibrahim
2026-03-04 14:35:04 -08:00
parent 7374a805fb
commit b747312f7a
4 changed files with 172 additions and 5 deletions

View File

@@ -1908,7 +1908,26 @@ impl App {
// but tui-textarea expects \n. Normalize CR to LF.
// [tui-textarea]: https://github.com/rhysd/tui-textarea/blob/4d18622eeac13b309e0ff6a55a46ac6706da68cf/src/textarea.rs#L782-L783
// [iTerm2]: https://github.com/gnachman/iTerm2/blob/5d0c0d9f68523cbd0494dad5422998964a2ecd8d/sources/iTermPasteHelper.m#L206-L216
let raw_char_count = pasted.chars().count();
let raw_cr_count = pasted.chars().filter(|ch| *ch == '\r').count();
let raw_lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let raw_preview: String = pasted.chars().take(120).collect();
let pasted = pasted.replace("\r", "\n");
let normalized_char_count = pasted.chars().count();
let normalized_cr_count = pasted.chars().filter(|ch| *ch == '\r').count();
let normalized_lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let normalized_preview: String = pasted.chars().take(120).collect();
tracing::error!(
raw_char_count,
raw_cr_count,
raw_lf_count,
normalized_char_count,
normalized_cr_count,
normalized_lf_count,
raw_preview = %raw_preview.escape_debug(),
normalized_preview = %normalized_preview.escape_debug(),
"handling tui paste event"
);
self.chat_widget.handle_paste(pasted);
}
TuiEvent::Draw => {

View File

@@ -760,9 +760,26 @@ impl ChatComposer {
if self.voice_state.voice.is_some() {
return false;
}
let raw_char_count = pasted.chars().count();
let raw_cr_count = pasted.chars().filter(|ch| *ch == '\r').count();
let raw_lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let raw_preview: String = pasted.chars().take(120).collect();
let pasted = pasted.replace("\r\n", "\n").replace('\r', "\n");
let char_count = pasted.chars().count();
let normalized_lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let normalized_preview: String = pasted.chars().take(120).collect();
if char_count > LARGE_PASTE_CHAR_THRESHOLD {
tracing::error!(
raw_char_count,
raw_cr_count,
raw_lf_count,
normalized_char_count = char_count,
normalized_lf_count,
threshold = LARGE_PASTE_CHAR_THRESHOLD,
raw_preview = %raw_preview.escape_debug(),
normalized_preview = %normalized_preview.escape_debug(),
"composer handle_paste classified as large paste"
);
let placeholder = self.next_large_paste_placeholder(char_count);
self.textarea.insert_element(&placeholder);
self.pending_pastes.push((placeholder, pasted));
@@ -770,8 +787,28 @@ impl ChatComposer {
&& self.image_paste_enabled()
&& self.handle_paste_image_path(pasted.clone())
{
tracing::error!(
raw_char_count,
raw_cr_count,
raw_lf_count,
normalized_char_count = char_count,
normalized_lf_count,
raw_preview = %raw_preview.escape_debug(),
normalized_preview = %normalized_preview.escape_debug(),
"composer handle_paste classified as image path paste"
);
self.textarea.insert_str(" ");
} else {
tracing::error!(
raw_char_count,
raw_cr_count,
raw_lf_count,
normalized_char_count = char_count,
normalized_lf_count,
raw_preview = %raw_preview.escape_debug(),
normalized_preview = %normalized_preview.escape_debug(),
"composer handle_paste classified as plain text paste"
);
self.insert_str(&pasted);
}
self.paste_burst.clear_after_explicit_paste();
@@ -1558,6 +1595,10 @@ impl ChatComposer {
} = input
{
if self.paste_burst.try_append_char_if_active(ch, now) {
tracing::error!(
ch = %ch.escape_debug(),
"non-ascii char appended to active paste burst buffer"
);
return (InputResult::None, true);
}
// Non-ASCII input often comes from IMEs and can arrive in quick bursts.
@@ -1566,15 +1607,31 @@ impl ChatComposer {
// any existing burst buffer (including a pending first char from the ASCII path) so
// we don't carry that transient state forward.
if let Some(pasted) = self.paste_burst.flush_before_modified_input() {
let char_count = pasted.chars().count();
let preview: String = pasted.chars().take(120).collect();
tracing::error!(
char_count,
preview = %preview.escape_debug(),
"flushed buffered paste before non-ascii input handling"
);
self.handle_paste(pasted);
}
if let Some(decision) = self.paste_burst.on_plain_char_no_hold(now) {
match decision {
CharDecision::BufferAppend => {
tracing::error!(
ch = %ch.escape_debug(),
"non-ascii input appended to paste burst buffer"
);
self.paste_burst.append_char_to_buffer(ch, now);
return (InputResult::None, true);
}
CharDecision::BeginBuffer { retro_chars } => {
tracing::error!(
ch = %ch.escape_debug(),
retro_chars,
"non-ascii input triggered paste burst BeginBuffer"
);
// For non-ASCII we inserted prior chars immediately, so if this turns out
// to be paste-like we need to retroactively grab & remove the already-
// inserted prefix from the textarea before buffering the burst.
@@ -1601,6 +1658,13 @@ impl ChatComposer {
}
}
if let Some(pasted) = self.paste_burst.flush_before_modified_input() {
let char_count = pasted.chars().count();
let preview: String = pasted.chars().take(120).collect();
tracing::error!(
char_count,
preview = %preview.escape_debug(),
"flushed buffered paste before default non-ascii input"
);
self.handle_paste(pasted);
}
self.textarea.input(input);
@@ -2422,6 +2486,10 @@ impl ChatComposer {
&& !in_slash_context
&& self.paste_burst.append_newline_if_active(now)
{
tracing::error!(
in_slash_context,
"paste burst active in submit path: intercepted Enter and appended newline"
);
return (InputResult::None, true);
}
@@ -2907,10 +2975,25 @@ impl ChatComposer {
fn handle_paste_burst_flush(&mut self, now: Instant) -> bool {
match self.paste_burst.flush_if_due(now) {
FlushResult::Paste(pasted) => {
let char_count = pasted.chars().count();
let cr_count = pasted.chars().filter(|ch| *ch == '\r').count();
let lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let preview: String = pasted.chars().take(120).collect();
tracing::error!(
char_count,
cr_count,
lf_count,
preview = %preview.escape_debug(),
"flushing buffered paste burst as explicit paste"
);
self.handle_paste(pasted);
true
}
FlushResult::Typed(ch) => {
tracing::error!(
ch = %ch.escape_debug(),
"flushing held first char from paste burst as typed input"
);
self.textarea.insert_str(ch.to_string().as_str());
self.sync_popups();
true
@@ -2962,6 +3045,9 @@ impl ChatComposer {
&& self.paste_burst.is_active()
&& self.paste_burst.append_newline_if_active(now)
{
tracing::error!(
"paste burst active in input-basic path: intercepted Enter and appended newline"
);
return (InputResult::None, true);
}
@@ -2990,6 +3076,11 @@ impl ChatComposer {
return (InputResult::None, true);
}
CharDecision::BeginBuffer { retro_chars } => {
tracing::error!(
ch = %ch.escape_debug(),
retro_chars,
"paste burst entered BeginBuffer on ascii input"
);
let cur = self.textarea.cursor();
let txt = self.textarea.text();
let safe_cur = Self::clamp_to_char_boundary(txt, cur);
@@ -3008,17 +3099,32 @@ impl ChatComposer {
// fall through to normal insertion below.
}
CharDecision::BeginBufferFromPending => {
tracing::error!(
ch = %ch.escape_debug(),
"paste burst entered BeginBufferFromPending on ascii input"
);
// First char was held; now append the current one.
self.paste_burst.append_char_to_buffer(ch, now);
return (InputResult::None, true);
}
CharDecision::RetainFirstChar => {
tracing::error!(
ch = %ch.escape_debug(),
"paste burst retained first ascii char pending classification"
);
// Keep the first fast char pending momentarily.
return (InputResult::None, true);
}
}
}
if let Some(pasted) = self.paste_burst.flush_before_modified_input() {
let char_count = pasted.chars().count();
let preview: String = pasted.chars().take(120).collect();
tracing::error!(
char_count,
preview = %preview.escape_debug(),
"flushed buffered paste before modified char input"
);
self.handle_paste(pasted);
}
}
@@ -3032,6 +3138,13 @@ impl ChatComposer {
if !matches!(input.code, KeyCode::Char(_) | KeyCode::Enter)
&& let Some(pasted) = self.paste_burst.flush_before_modified_input()
{
let char_count = pasted.chars().count();
let preview: String = pasted.chars().take(120).collect();
tracing::error!(
char_count,
preview = %preview.escape_debug(),
"flushed buffered paste before non-char input"
);
self.handle_paste(pasted);
}
// For non-char inputs (or after flushing), handle normally.

View File

@@ -420,8 +420,10 @@ pub async fn run_main(mut cli: Cli, arg0_paths: Arg0DispatchPaths) -> std::io::R
std::process::exit(1);
}
let log_dir = codex_core::config::log_dir(&config)?;
std::fs::create_dir_all(&log_dir)?;
let log_path = PathBuf::from("/Users/aibrahim/.codex/log/codex-tui.log");
if let Some(parent) = log_path.parent() {
std::fs::create_dir_all(parent)?;
}
// Open (or create) your log file, appending to it.
let mut log_file_opts = OpenOptions::new();
log_file_opts.create(true).append(true);
@@ -436,7 +438,7 @@ pub async fn run_main(mut cli: Cli, arg0_paths: Arg0DispatchPaths) -> std::io::R
log_file_opts.mode(0o600);
}
let log_file = log_file_opts.open(log_dir.join("codex-tui.log"))?;
let log_file = log_file_opts.open(&log_path)?;
// Wrap file in nonblocking writer.
let (non_blocking, _guard) = non_blocking(log_file);
@@ -508,7 +510,7 @@ pub async fn run_main(mut cli: Cli, arg0_paths: Arg0DispatchPaths) -> std::io::R
.await
.map(|db| log_db::start(db).with_filter(env_filter()));
let _ = tracing_subscriber::registry()
let init_result = tracing_subscriber::registry()
.with(file_layer)
.with(feedback_layer)
.with(feedback_metadata_layer)
@@ -516,6 +518,18 @@ pub async fn run_main(mut cli: Cli, arg0_paths: Arg0DispatchPaths) -> std::io::R
.with(otel_logger_layer)
.with(otel_tracing_layer)
.try_init();
if let Err(err) = init_result {
#[allow(clippy::print_stderr)]
{
eprintln!(
"Failed to initialize tracing subscriber for {}: {err}",
log_path.display()
);
}
return Err(std::io::Error::other(format!(
"failed to initialize tracing subscriber: {err}"
)));
}
run_ratatui_app(
cli,

View File

@@ -237,6 +237,13 @@ impl<S: EventSource + Default + Unpin> TuiEventStream<S> {
fn map_crossterm_event(&mut self, event: Event) -> Option<TuiEvent> {
match event {
Event::Key(key_event) => {
tracing::error!(
kind = ?key_event.kind,
code = ?key_event.code,
modifiers = ?key_event.modifiers,
state = ?key_event.state,
"received crossterm key event"
);
#[cfg(unix)]
if crate::tui::job_control::SUSPEND_KEY.is_press(key_event) {
let _ = self.suspend_context.suspend(&self.alt_screen_active);
@@ -245,7 +252,21 @@ impl<S: EventSource + Default + Unpin> TuiEventStream<S> {
Some(TuiEvent::Key(key_event))
}
Event::Resize(_, _) => Some(TuiEvent::Draw),
Event::Paste(pasted) => Some(TuiEvent::Paste(pasted)),
Event::Paste(pasted) => {
let char_count = pasted.chars().count();
let cr_count = pasted.chars().filter(|ch| *ch == '\r').count();
let lf_count = pasted.chars().filter(|ch| *ch == '\n').count();
let preview: String = pasted.chars().take(120).collect();
let escaped_preview = preview.escape_debug().to_string();
tracing::error!(
char_count,
cr_count,
lf_count,
preview = %escaped_preview,
"received crossterm paste event"
);
Some(TuiEvent::Paste(pasted))
}
Event::FocusGained => {
self.terminal_focused.store(true, Ordering::Relaxed);
crate::terminal_palette::requery_default_colors();