From f8c8a33a4b1615cd7f00b0c2c4fd1f71d6af5c1b Mon Sep 17 00:00:00 2001 From: biscoito Date: Wed, 16 Sep 2026 19:54:58 -0300 Subject: [PATCH] feat: use tracing and RUST_LOG for logging (#57) --- CHANGELOG.md | 3 + Cargo.lock | 105 ++++++++++++ Cargo.toml | 2 + README.md | 28 ++- src/app.rs | 69 +++++--- src/commands.rs | 35 +++- src/database.rs | 51 +++++- src/global/events.rs | 2 + src/global/goto.rs | 9 +- src/global/log.rs | 159 ++++++++++++++--- src/hex/names.rs | 12 +- src/hex/search.rs | 23 ++- src/hex/selection.rs | 10 +- src/hex/strings.rs | 37 +++- src/hex/truncate.rs | 11 ++ src/initfile.rs | 49 ++++-- src/logging.rs | 394 +++++++++++++++++++++++++++++++++++++++++++ src/main.rs | 99 ++++++++--- src/text/events.rs | 3 +- 19 files changed, 975 insertions(+), 126 deletions(-) create mode 100644 src/logging.rs diff --git a/CHANGELOG.md b/CHANGELOG.md index 46b6306..ec702f0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,9 @@ - Header view: new view to inspect ELF and PE executables. - Added a command to change the view (same as pressing `Tab`). Example: `:set view hex` (possible values are `text`, `hex`, and `header`). It can be used in `~/.dz6init` to set the default view when dz6 is loaded. - Added support for comments / lines starting with `#` in `~/.dz6init`. +- Logging: dz6 now uses `tracing`, so the `RUST_LOG` environment variable controls what is logged. Example: `RUST_LOG=debug dz6 file.bin`. Messages are shown in the log window (`Alt+l`) and also written to `stderr` if you redirect it (`dz6 file.bin 2> dz6.log`). +- Log window: shows the time, level, and module of each message. It scrolls with `j`/`k`, `f`/`b`, `g`/`G`, and `h`/`l`, and `c` clears it. +- Errors that were silent before are logged now, like opening a file without write permission, a broken `.dz6` database file, an invalid regex in the string list, and a `:w` that fails. ## Breaking changes: - `Tab` cycles through available views now (`Enter` no longer does that). diff --git a/Cargo.lock b/Cargo.lock index e70cc91..271ea91 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -539,6 +539,8 @@ dependencies = [ "serde", "shell-words", "toml", + "tracing", + "tracing-subscriber", "tui-input", ] @@ -968,6 +970,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.8.3" @@ -1054,6 +1065,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num-conv" version = "0.2.2" @@ -1692,6 +1712,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shell-words" version = "1.1.1" @@ -1935,6 +1964,15 @@ dependencies = [ "syn 3.0.3", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "time" version = "0.3.55" @@ -1995,6 +2033,67 @@ version = "1.1.2+spec-1.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7d56353a2a665ad0f41a421187180aab746c8c325620617ad883a99a1cbe66d2" +[[package]] +name = "tracing" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.119", +] + +[[package]] +name = "tracing-core" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + [[package]] name = "tui-input" version = "0.15.3" @@ -2065,6 +2164,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "version_check" version = "0.9.5" diff --git a/Cargo.toml b/Cargo.toml index a15a3d6..986fb20 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -28,6 +28,8 @@ regex = "1.11.2" serde = { version = "1.0.228", features = ["derive"] } shell-words = "1.1.0" toml = "1.0.1" +tracing = "0.1.44" +tracing-subscriber = { version = "0.3.23", features = ["env-filter"] } tui-input = "0.15.0" # The profile that 'dist' will build with diff --git a/README.md b/README.md index 05954b9..6277111 100644 --- a/README.md +++ b/README.md @@ -95,7 +95,7 @@ Once you load a file in **dz6**, you can use the commands below. | Key | Action | Tips | | ------- | ---------------- | -------------------------------------------------------------- | | `Tab` | Switch views | Cycle through Hex, Text, and Headers. Backtab: Cycle backward. | -| `Alt+l` | Open log window | | +| `Alt+l` | Open log window | See [Logging](#logging) | | `:` | Open command bar | See [Commands](#commands) | #### Commands @@ -256,6 +256,32 @@ The Header view is a new view (expected in v0.8.0) available for executable file | `Space` | Change output numeric base | Output numbers in hexadecimal (default) or decimal | | `Enter` | Follow a field value | For applicable fields (e.g., `AddressOfEntryPoint` in the PE Optional Header), follow their value in the Hex view. | +## Logging + +**dz6** uses [tracing](https://docs.rs/tracing), so the `RUST_LOG` environment variable controls what is logged, as in any other Rust program: + + RUST_LOG=debug dz6 file.bin + RUST_LOG=dz6::hex::search=trace dz6 file.bin + +The levels are `error`, `warn`, `info`, `debug`, and `trace`. If you don't set `RUST_LOG`, dz6 logs at `info` level and the crates it uses at `warn`. + +Messages are shown in the log window (`Alt+l`), which keeps the most recent ones. They also go to `stderr`, but since the interface takes over the terminal, writing there while dz6 is running would mess up the screen. So it only happens if you redirect `stderr` somewhere else: + + dz6 file.bin 2> dz6.log + +If you don't redirect it, the messages are printed after you quit dz6: warnings and errors only, or everything that matched your `RUST_LOG`, if you set one. + +### Log window + +| Key | Action | Tips | +| ----------------------- | -------------------- | --------------------------------------------- | +| `j` / `k` | Scroll one message | Down and Up arrow keys also work | +| `f` / `b` | Scroll one page | PgDown and PgUp also work | +| `g` / `G` | First / last message | Home and End also work | +| `h` / `l` | Scroll sideways | Left and Right arrow keys also work | +| `c` | Clear the messages | Only clears the window, not a redirected file | +| `q` | Close the window | `Esc` also works | + ## FAQ **1. I'm on a Mac. How am I supposed to use `Alt` key?!** diff --git a/src/app.rs b/src/app.rs index 74ac231..08b50dd 100644 --- a/src/app.rs +++ b/src/app.rs @@ -11,11 +11,13 @@ use goblin::Object; use goblin::error; use mmap_io::{MemoryMappedFile, MmapMode}; use ratatui::{Frame, layout::Rect, widgets::ListState}; +use tracing::{debug, error, info, instrument, warn}; use crate::{ config::*, editor::*, global::calculator::Calculator, + global::log::LogView, header::header_view::{Elf, HeaderView, Pe}, hex::{hex_view::HexView, strings::FoundString}, input_history::InputHistory, @@ -76,8 +78,7 @@ pub struct App { pub hex_view: HexView, pub last_error: Dz6Error, pub list_state: ListState, - pub log_scroll_offset: (u16, u16), - pub logs: Vec, + pub log_view: LogView, pub reader: Reader, pub running: bool, pub screen: Rect, @@ -123,8 +124,7 @@ impl App { ..Default::default() }, list_state: ListState::default(), - log_scroll_offset: (0, 0), - logs: Vec::with_capacity(100), + log_view: LogView::default(), reader: Reader::new(), running: true, screen: Rect::default(), @@ -223,6 +223,11 @@ impl App { } /// load a file + #[instrument( + level = "debug", + skip_all, + fields(path = filepath, offset = initial_offset, read_only = read_only) + )] pub fn load_file( &mut self, filepath: &str, @@ -241,32 +246,46 @@ impl App { let meta = path.metadata()?; // We try to open file readwrite to use this later for saving - if !read_only && let Ok(file) = OpenOptions::new().read(true).write(true).open(path) { - self.file_info.file = Some(file); - } else { + if read_only { self.file_info.is_read_only = true; + } else { + match OpenOptions::new().read(true).write(true).open(path) { + Ok(file) => self.file_info.file = Some(file), + Err(error) => { + warn!(%error, "cannot open for writing, continuing read-only"); + self.file_info.is_read_only = true; + } + } } // We map it on memory readonly as changed to mapped memory also changes it on disk - if let Ok(mmap) = MemoryMappedFile::builder(path) + match MemoryMappedFile::builder(path) .mode(MmapMode::ReadOnly) .open() { - self.file_info.mmap = Some(mmap); - } else { - return Err(std::io::Error::other("could not open file")); + Ok(mmap) => self.file_info.mmap = Some(mmap), + Err(error) => { + error!(%error, "cannot memory map the file"); + return Err(std::io::Error::other("could not open file")); + } } self.file_info.size = meta.len() as usize; if self.file_info.size > 0 { - _ = self.id_file(); + match self.id_file() { + Ok(()) => debug!(kind = self.file_info.r#type, "file type identified"), + // most files are not executables, so this is normal + Err(error) => debug!(%error, "unknown file format"), + } } - self.log(format!( - "filesize: {} (0x{:x})", - self.file_info.size, self.file_info.size - )); + info!( + path = %self.file_info.path, + size = self.file_info.size, + read_only = self.file_info.is_read_only, + "file loaded" + ); if initial_offset != 0 { self.goto(0); @@ -274,20 +293,26 @@ impl App { self.goto(initial_offset); // try to load a database for this file, but continue otherwise - if self.config.database { - let _ = self.load_database(); + if self.config.database + && let Err(error) = self.load_database() + { + debug!(%error, "no database loaded"); } Ok(()) } pub fn reload_file(&mut self) { - let fp = self.file_info.path.clone(); - self.load_file(&fp, self.hex_view.offset, self.file_info.is_read_only) - .expect("could not reload the file"); + let path = self.file_info.path.clone(); + + if let Err(error) = self.load_file(&path, self.hex_view.offset, self.file_info.is_read_only) + { + error!(path = %path, %error, "could not reload the file"); + } } /// write what's cached to the actual file + #[instrument(name = "write", level = "debug", skip(self))] pub fn write_to_file(&mut self) -> io::Result<()> { if self.file_info.file.is_none() { return Err(io::Error::other("file not open")); @@ -311,7 +336,7 @@ impl App { } } - App::log(self, format!("{} bytes written to file", total_written)); + info!(bytes = total_written, "wrote changes to file"); self.hex_view.changed_bytes.clear(); Ok(()) } diff --git a/src/commands.rs b/src/commands.rs index 99030fd..4b9221a 100644 --- a/src/commands.rs +++ b/src/commands.rs @@ -10,6 +10,7 @@ use crate::app::Dz6Error; use clap::{Parser, Subcommand}; use ratatui::crossterm::event::{Event, KeyCode}; use std::io::Result; +use tracing::{debug, error, warn}; use tui_input::backend::crossterm::EventHandler; pub struct Commands; @@ -88,6 +89,19 @@ fn try_goto(app: &mut App, offset: &str) { } } +/// Writes the file and the database, logging whatever fails +fn write_and_save(app: &mut App) { + if let Err(error) = app.write_to_file() { + error!(%error, "could not write to file"); + } + + if app.config.database + && let Err(error) = app.save_database() + { + warn!(%error, "could not save the database"); + } +} + pub fn parse_command(app: &mut App, cmdline: &str) { if cmdline.is_empty() { app.state = UIState::Normal; @@ -95,7 +109,15 @@ pub fn parse_command(app: &mut App, cmdline: &str) { return; } - let args = shell_words::split(cmdline).unwrap_or_default(); + debug!(command = cmdline, "running command"); + + let args = match shell_words::split(cmdline) { + Ok(args) => args, + Err(error) => { + debug!(%error, "unbalanced quotes, treating the line as an offset"); + Vec::new() + } + }; let mut argv: Vec<&str> = Vec::with_capacity(args.len() + 1); argv.push("dz6"); @@ -109,19 +131,13 @@ pub fn parse_command(app: &mut App, cmdline: &str) { Some(Command::Q) => app.running = false, // write to file Some(Command::W) => { - let _ = app.write_to_file(); - if app.config.database { - let _ = app.save_database(); - } + write_and_save(app); app.dialog_renderer = None; app.state = UIState::Normal; } // write and quit Some(Command::Wq) | Some(Command::X) => { - let _ = app.write_to_file(); - if app.config.database { - let _ = app.save_database(); - } + write_and_save(app); app.dialog_renderer = None; app.running = false; } @@ -288,6 +304,7 @@ pub fn parse_command(app: &mut App, cmdline: &str) { }, Err(_) => { // goto as :offset + debug!(command = cmdline, "not a command, trying as an offset"); try_goto(app, cmdline); } } diff --git a/src/database.rs b/src/database.rs index 3617cd6..3797410 100644 --- a/src/database.rs +++ b/src/database.rs @@ -1,14 +1,17 @@ use std::collections::BTreeMap; use std::error::Error; use std::fs; +use std::io; use std::path::{Path, PathBuf}; use serde::{Deserialize, Serialize}; +use tracing::{debug, info, instrument, warn}; use crate::app::App; use crate::hex::{blocks::ColoredBlock, comment::Comment, hex_view::HexView}; impl App { + #[instrument(name = "save", level = "debug", skip(self))] pub fn save_database(&self) -> Result<(), Box> { let target_dir: &Path = Path::new(&self.file_info.path) .parent() @@ -21,8 +24,14 @@ impl App { && self.hex_view.comment_name_list.is_empty() && self.hex_view.blocks.is_empty() { - let _ = fs::remove_file(target_db); - let _ = fs::remove_file(cwd_db); + for stale in [target_db.as_path(), Path::new(&cwd_db)] { + match fs::remove_file(stale) { + Ok(()) => info!(path = %stale.display(), "removed empty database"), + Err(error) if error.kind() == io::ErrorKind::NotFound => {} + Err(error) => warn!(path = %stale.display(), %error, "cannot remove database"), + } + } + return Ok(()); } @@ -31,10 +40,29 @@ impl App { let toml_string = toml::to_string_pretty(&db)?; // try target's path or else current directory - fs::write(&target_db, &toml_string).or_else(|_| fs::write(&cwd_db, &toml_string))?; + let saved_to = match fs::write(&target_db, &toml_string) { + Ok(()) => target_db, + Err(error) => { + debug!( + path = %target_db.display(), + %error, + "cannot write next to the file, trying the current directory" + ); + fs::write(&cwd_db, &toml_string)?; + PathBuf::from(&cwd_db) + } + }; + + info!( + path = %saved_to.display(), + bytes = toml_string.len(), + "database saved" + ); Ok(()) } + + #[instrument(name = "load", level = "debug", skip(self))] pub fn load_database(&mut self) -> Result<(), Box> { let target_dir: &Path = Path::new(&self.file_info.path) .parent() @@ -43,8 +71,23 @@ impl App { let target_db: PathBuf = target_dir.join(&cwd_db); let data = fs::read_to_string(&cwd_db).or_else(|_| fs::read_to_string(&target_db))?; - let db = toml::from_str::(&data)?; + let db = match toml::from_str::(&data) { + Ok(db) => db, + Err(error) => { + warn!(%error, "ignoring malformed database"); + return Err(error.into()); + } + }; + + info!( + bookmarks = db.bookmarks.len(), + comments = db.comments.len(), + blocks = db.blocks.len(), + "database loaded" + ); + self.hex_view = hex_view_from_db(db); + Ok(()) } } diff --git a/src/global/events.rs b/src/global/events.rs index fb59889..d402a92 100644 --- a/src/global/events.rs +++ b/src/global/events.rs @@ -15,6 +15,8 @@ pub fn handle_global_events(app: &mut App, key: KeyEvent) -> Result { KeyCode::Char('l') if key.modifiers.contains(KeyModifiers::ALT) => { app.state = UIState::DialogLog; app.dialog_renderer = Some(global::log::dialog_log_draw); + // show the newest messages + app.log_view.scroll_to_end(); } // command bar KeyCode::Char(':') => { diff --git a/src/global/goto.rs b/src/global/goto.rs index ec30a23..2b1b2cb 100644 --- a/src/global/goto.rs +++ b/src/global/goto.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::app::App; use crate::editor::AppView; @@ -70,6 +72,11 @@ impl App { self.editor_view = AppView::Hex; } - App::log(self, format!("goto: {:x}", offset)); + trace!( + offset, + page_start = self.reader.page_start, + page_end = self.reader.page_end, + "cursor moved" + ); } } diff --git a/src/global/log.rs b/src/global/log.rs index 91c559d..24df8ed 100644 --- a/src/global/log.rs +++ b/src/global/log.rs @@ -1,53 +1,156 @@ -use ratatui::crossterm::event::{KeyCode, KeyEvent}; -use ratatui::layout::Alignment; -use ratatui::widgets::{Block, Paragraph, Wrap}; -use ratatui::{Frame, widgets::Clear}; +// The log window (Alt+l). It just shows what crate::logging collected + +use std::borrow::Cow; use std::io::Result; +use ratatui::Frame; +use ratatui::crossterm::event::{KeyCode, KeyEvent}; +use ratatui::style::{Color, Modifier, Style}; +use ratatui::text::{Line, Span, Text}; +use ratatui::widgets::{Block, Clear, Paragraph}; +use tracing::Level; + use crate::util::center_widget; -use crate::{app::App, editor::UIState}; +use crate::{app::App, editor::UIState, logging}; + +// how many columns the left/right keys scroll +const COLUMN_STEP: u16 = 8; + +/// Log window state +#[derive(Default)] +pub struct LogView { + /// scroll position, as (record, column) + pub scroll: (u16, u16), + /// how many records fit on the screen; set while drawing + pub height: u16, +} -impl App { - pub fn log(&mut self, text: String) { - self.logs.push(text) +impl LogView { + /// Jump to the newest records. The draw function fixes the exact position + pub fn scroll_to_end(&mut self) { + self.scroll = (u16::MAX, 0); } } +// we use the terminal colors here so the levels are readable in any theme +fn level_style(level: Level) -> Style { + Style::new().fg(match level { + Level::ERROR => Color::LightRed, + Level::WARN => Color::LightYellow, + Level::INFO => Color::LightGreen, + Level::DEBUG => Color::LightBlue, + Level::TRACE => Color::Gray, + }) +} + pub fn dialog_log_draw(app: &mut App, frame: &mut Frame) { - let text = format!("{:?}\n\n{}", app.reader, app.logs.join("\n")); + let area = frame.area(); + let dialog_area = center_widget( + area.width.saturating_sub(5), + area.height.saturating_sub(5), + area, + ); + + let buffer = logging::buffer().lock(); + let records = buffer.records(); + let dropped = buffer.dropped(); + + let title = if dropped == 0 { + format!(" Log ({}) ", records.len()) + } else { + format!(" Log ({}, {} dropped) ", records.len(), dropped) + }; + + let block = Block::bordered() + .title(Line::from(title).centered()) + .title_bottom(Line::from(format!(" RUST_LOG={} ", logging::filter())).centered()); - let para = Paragraph::new(text) + let inner = block.inner(dialog_area); + app.log_view.height = inner.height; + + // one record per line, so we know exactly where the last page starts and + // we only need to build the lines that are visible + let visible = inner.height as usize; + let last = u16::try_from(records.len().saturating_sub(visible)).unwrap_or(u16::MAX); + app.log_view.scroll.0 = app.log_view.scroll.0.min(last); + + let dim = Style::new().add_modifier(Modifier::DIM); + + let text: Text = if records.is_empty() { + Text::from(Line::styled( + "Nothing logged yet. Run with RUST_LOG=debug for more detail.", + dim, + )) + } else { + records + .iter() + .skip(app.log_view.scroll.0 as usize) + .take(visible) + .map(|record| { + let scope: Cow = match record.span { + Some(span) => Cow::Owned(format!("{}{{{}}}", record.module(), span)), + None => Cow::Borrowed(record.module()), + }; + + Line::from(vec![ + Span::styled(record.time().to_string(), dim), + Span::raw(" "), + Span::styled( + format!("{:>5}", record.level.as_str()), + level_style(record.level), + ), + Span::raw(" "), + Span::styled(scope, dim), + Span::styled(": ", dim), + Span::raw(record.message.as_str()), + ]) + }) + .collect() + }; + + let paragraph = Paragraph::new(text) .style(app.config.theme.dialog) - .wrap(Wrap { trim: true }) - .block( - Block::bordered() - .title(" Log ") - .title_alignment(Alignment::Center), - ) - .scroll(app.log_scroll_offset); - - let width = frame.area().width - 5; - let height = frame.area().height - 5; - let dialog_area = center_widget(width, height, frame.area()); + .block(block) + .scroll((0, app.log_view.scroll.1)); frame.render_widget(Clear, dialog_area); - frame.render_widget(para, dialog_area); + frame.render_widget(paragraph, dialog_area); } pub fn dialog_log_events(app: &mut App, key: KeyEvent) -> Result { + let page = app.log_view.height.max(1); + match key.code { - // close log dialog - KeyCode::Esc => { + // close log window + KeyCode::Esc | KeyCode::Char('q') => { app.dialog_renderer = None; app.state = UIState::Normal; } - KeyCode::Down => { - app.log_scroll_offset.0 += 1; + // scroll; the draw function clamps it to the last record + KeyCode::Down | KeyCode::Char('j') => { + app.log_view.scroll.0 = app.log_view.scroll.0.saturating_add(1); } - KeyCode::Up => { - app.log_scroll_offset.0 = app.log_scroll_offset.0.saturating_sub(1); + KeyCode::Up | KeyCode::Char('k') => { + app.log_view.scroll.0 = app.log_view.scroll.0.saturating_sub(1); } + KeyCode::PageDown | KeyCode::Char('f') => { + app.log_view.scroll.0 = app.log_view.scroll.0.saturating_add(page); + } + KeyCode::PageUp | KeyCode::Char('b') => { + app.log_view.scroll.0 = app.log_view.scroll.0.saturating_sub(page); + } + KeyCode::Right | KeyCode::Char('l') => { + app.log_view.scroll.1 = app.log_view.scroll.1.saturating_add(COLUMN_STEP); + } + KeyCode::Left | KeyCode::Char('h') => { + app.log_view.scroll.1 = app.log_view.scroll.1.saturating_sub(COLUMN_STEP); + } + KeyCode::Home | KeyCode::Char('g') => app.log_view.scroll = (0, 0), + KeyCode::End | KeyCode::Char('G') => app.log_view.scroll_to_end(), + // clear the messages + KeyCode::Char('c') => logging::buffer().lock().clear(), _ => {} } + Ok(false) } diff --git a/src/hex/names.rs b/src/hex/names.rs index fb93979..a581c7b 100644 --- a/src/hex/names.rs +++ b/src/hex/names.rs @@ -9,6 +9,8 @@ use ratatui::{ use ratatui::crossterm::event::{Event, KeyCode}; use std::io::Result; +use tracing::error; + use crate::{app::App, commands::Commands, editor::UIState, util::center_widget}; pub fn dialog_names_draw(app: &mut App, frame: &mut Frame) { @@ -82,11 +84,11 @@ pub fn dialog_names_events(app: &mut App, event: &Event) -> Result { } KeyCode::Enter => { if let Some(choice) = app.hex_view.names_list_state.selected() { - if choice > app.hex_view.comment_name_list.len() { - App::log( - app, - "wtf {choice} is greater than `app.hex_mode.comments.len()`, dunno how" - .to_string(), + if choice >= app.hex_view.comment_name_list.len() { + error!( + choice, + names = app.hex_view.comment_name_list.len(), + "selected name is out of range" ); return Ok(true); } diff --git a/src/hex/search.rs b/src/hex/search.rs index f8bfd85..c0b1a50 100644 --- a/src/hex/search.rs +++ b/src/hex/search.rs @@ -4,6 +4,7 @@ use ratatui::Frame; use ratatui::crossterm::event::{Event, KeyCode}; use ratatui::widgets::Paragraph; use std::io::Result; +use tracing::debug; use tui_input::Input; use tui_input::backend::crossterm::EventHandler; @@ -52,12 +53,20 @@ pub fn hex_string_to_u8(hex_string: &str) -> Option> { pub fn search>(app: &mut App, needle: T) -> Option { let text = needle.as_ref(); let filesize = app.file_info.size; - let buffer = app.file_info.get_buffer(); if filesize == 0 || text.is_empty() { return None; } + debug!( + bytes = text.len(), + from = app.hex_view.offset, + backward = app.hex_view.search.direction == SearchDirection::Backward, + "searching" + ); + + let buffer = app.file_info.get_buffer(); + let ofs = if app.hex_view.search.direction == SearchDirection::Forward { let start = app.hex_view.offset.checked_add(1)?; if start < filesize { @@ -74,8 +83,9 @@ pub fn search>(app: &mut App, needle: T) -> Option { } }; - if ofs.is_some() { - return ofs; + if let Some(offset) = ofs { + debug!(offset, wrapped = false, "pattern found"); + return Some(offset); } // ofs is None, check wrap setting @@ -86,12 +96,15 @@ pub fn search>(app: &mut App, needle: T) -> Option { memchr::memmem::rfind(buffer, text) }; - if ofs.is_some() { - return ofs; + if let Some(offset) = ofs { + debug!(offset, wrapped = true, "pattern found"); + return Some(offset); } } + debug!(bytes = text.len(), "pattern not found"); crate::beep!(); + None } diff --git a/src/hex/selection.rs b/src/hex/selection.rs index aa5fa8e..317ed0f 100644 --- a/src/hex/selection.rs +++ b/src/hex/selection.rs @@ -1,6 +1,7 @@ use crossterm::event::KeyModifiers; use ratatui::crossterm::event::{KeyCode, KeyEvent}; use std::io::Result; +use tracing::warn; use crate::app::App; use crate::editor::UIState; @@ -193,8 +194,13 @@ pub fn select_events(app: &mut App, key: KeyEvent) -> Result { s.push_str(&format!("{:02X}", byte)); } } - if let Ok(clip) = app.clipboard.as_mut() { - let _ = clip.set_text(s); + match app.clipboard.as_mut() { + Ok(clip) => { + if let Err(error) = clip.set_text(s) { + warn!(%error, "could not copy to the clipboard"); + } + } + Err(error) => warn!(%error, "no clipboard available"), } app.state = UIState::Normal; app.hex_view.selection.clear(); diff --git a/src/hex/strings.rs b/src/hex/strings.rs index 3a708cb..f3772bb 100644 --- a/src/hex/strings.rs +++ b/src/hex/strings.rs @@ -13,6 +13,7 @@ use std::io::Result; use crate::{app::App, commands::Commands, editor::UIState, util::center_widget}; use regex::{Regex, RegexBuilder}; +use tracing::{debug, error, info, warn}; pub struct FoundString { pub offset: usize, @@ -98,10 +99,11 @@ pub fn dialog_strings_events(app: &mut App, key: KeyEvent) -> Result { } KeyCode::Enter => { if let Some(choice) = app.list_state.selected() { - if choice > app.strings.len() { - App::log( - app, - "wtf {choice} is greater than `app.strings.len()`, dunno how".to_string(), + if choice >= app.strings.len() { + error!( + choice, + strings = app.strings.len(), + "selected string is out of range" ); return Ok(true); } @@ -191,12 +193,20 @@ impl Commands { // Read the entire file by blocks and find strings in them - let default_regex = Regex::new(".*").unwrap(); - // let re = Regex::new(&self.string_regex).unwrap_or(default_regex); - let re = RegexBuilder::new(&app.string_regex) + let re = match RegexBuilder::new(&app.string_regex) .case_insensitive(true) .build() - .unwrap_or(default_regex); + { + Ok(re) => re, + Err(error) => { + warn!( + regex = %app.string_regex, + %error, + "invalid filter regex, listing every string" + ); + Regex::new(".*").expect("a literal regex always builds") + } + }; let buffer = app.file_info.get_buffer(); for (offset, byte) in buffer.iter().enumerate() { @@ -211,7 +221,10 @@ impl Commands { size: siz, }); if app.strings.len() >= app.config.maximum_strings_to_show { - // too many strings :( + debug!( + maximum = app.config.maximum_strings_to_show, + "string list truncated" + ); break; } } @@ -219,5 +232,11 @@ impl Commands { siz = 0; } } + + info!( + strings = app.strings.len(), + minimum_length = app.config.minimum_string_length, + "scanned for strings" + ); } } diff --git a/src/hex/truncate.rs b/src/hex/truncate.rs index 8d3e619..d54eb59 100644 --- a/src/hex/truncate.rs +++ b/src/hex/truncate.rs @@ -1,6 +1,7 @@ use crossterm::event::{Event, KeyCode}; use ratatui::Frame; use std::io::{Result, Write}; +use tracing::info; use crate::{ app::App, @@ -22,6 +23,11 @@ pub fn dialog_truncate_events(app: &mut App, event: &Event) -> Result { if let KeyCode::Char('y') = key.code && let Some(f) = &app.file_info.file { + info!( + size = app.file_info.size, + new_size = app.hex_view.offset + 1, + "truncating file" + ); f.set_len((app.hex_view.offset + 1) as u64)?; app.reload_file(); } @@ -49,6 +55,11 @@ pub fn dialog_reverse_truncate_events(app: &mut App, event: &Event) -> Result Result<(), Box> { - let home = UserDirs::new(); - - if let Some(home) = home { - let home = home.home_dir().to_owned(); - let path = home.join(".dz6init"); - let data = fs::read_to_string(path)?; - - for cmdline in data - .lines() - .map(str::trim) - .filter(|line| !line.starts_with('#')) - { - parse_command(self, cmdline); + /// Runs the commands in `~/.dz6init`. It's fine if the file is not there + #[instrument(name = "read", level = "debug", skip(self))] + pub fn read_initfile(&mut self) { + let Some(dirs) = UserDirs::new() else { + warn!("no home directory, skipping the init file"); + return; + }; + + let path = dirs.home_dir().join(".dz6init"); + + let data = match fs::read_to_string(&path) { + Ok(data) => data, + Err(error) if error.kind() == io::ErrorKind::NotFound => { + debug!(path = %path.display(), "no init file"); + return; + } + Err(error) => { + warn!(path = %path.display(), %error, "cannot read the init file"); + return; } + }; + + let mut commands = 0; + + for cmdline in data + .lines() + .map(str::trim) + .filter(|line| !line.is_empty() && !line.starts_with('#')) + { + parse_command(self, cmdline); + commands += 1; } - Ok(()) + info!(path = %path.display(), commands, "init file loaded"); } } diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 0000000..e505041 --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,394 @@ +// Every log message in dz6 goes through tracing, so RUST_LOG controls all of +// them, as usual in Rust programs: +// +// RUST_LOG=debug dz6 file.bin +// RUST_LOG=dz6::hex::search=trace dz6 file.bin +// +// Messages go to the log window (Alt+l) and to stderr. The TUI owns the +// terminal, so writing to stderr while dz6 is running would mess up the +// screen. That's why we only do it when stderr is redirected somewhere else +// (dz6 file.bin 2> dz6.log). Otherwise the messages stay in the ring buffer +// and flush() prints them after the terminal is restored. + +use std::{ + collections::VecDeque, + env, + fmt::{self, Write as _}, + io::{self, IsTerminal}, + sync::{LazyLock, Mutex, MutexGuard, OnceLock}, +}; + +use chrono::{DateTime, Local}; +use tracing::{ + Event, Level, Subscriber, + field::{Field, Visit}, + warn, +}; +use tracing_subscriber::{ + EnvFilter, + fmt::{format::Writer, time::FormatTime}, + layer::{Context, Layer, SubscriberExt}, + registry::LookupSpan, + util::SubscriberInitExt, +}; + +/// Filter used when RUST_LOG is not set: dz6 at info, other crates at warn +pub const DEFAULT_FILTER: &str = concat!("warn,", env!("CARGO_CRATE_NAME"), "=info"); + +/// How many messages we keep for the log window. The oldest ones go first +const CAPACITY: usize = 2048; + +/// Time format used in the log window +const TIME_FORMAT: &str = "%H:%M:%S%.3f"; + +/// Same thing for stderr, but with the date, as it usually goes to a file +const STREAM_TIME_FORMAT: &str = "%Y-%m-%d %H:%M:%S%.3f"; + +/// Local time, so the window and stderr show the same clock +struct LocalTime; + +impl FormatTime for LocalTime { + fn format_time(&self, writer: &mut Writer<'_>) -> fmt::Result { + write!(writer, "{}", Local::now().format(STREAM_TIME_FORMAT)) + } +} + +/// A single log message +pub struct Record { + pub time: DateTime, + pub level: Level, + /// module that logged it, like dz6::hex::search + pub target: &'static str, + /// innermost span, if the message was logged inside one + pub span: Option<&'static str>, + /// the message itself followed by its fields, like "saved bytes=12" + pub message: String, +} + +impl Record { + /// Writes something like "12:34:56.789 WARN dz6::database{save}: message" + fn write_to(&self, out: &mut impl io::Write) -> io::Result<()> { + write!( + out, + "{} {:>5} {}", + self.time.format(TIME_FORMAT), + self.level.as_str(), + self.target + )?; + + if let Some(span) = self.span { + write!(out, "{{{span}}}")?; + } + + writeln!(out, ": {}", self.message) + } + + /// Time as shown in the log window + pub fn time(&self) -> impl fmt::Display { + self.time.format(TIME_FORMAT) + } + + /// Target without our own crate name, so lines in the window are shorter + pub fn module(&self) -> &'static str { + self.target + .strip_prefix(concat!(env!("CARGO_CRATE_NAME"), "::")) + .unwrap_or(self.target) + } +} + +/// Ring buffer with the most recent messages +pub struct Buffer { + records: VecDeque, + dropped: usize, +} + +impl Default for Buffer { + fn default() -> Self { + Buffer { + records: VecDeque::with_capacity(256), + dropped: 0, + } + } +} + +impl Buffer { + /// Messages we still have, oldest first + pub fn records(&self) -> &VecDeque { + &self.records + } + + /// How many messages we had to throw away because the buffer was full + pub fn dropped(&self) -> usize { + self.dropped + } + + pub fn clear(&mut self) { + self.records.clear(); + self.dropped = 0; + } + + fn push(&mut self, record: Record) { + if self.records.len() == CAPACITY { + self.records.pop_front(); + self.dropped += 1; + } + + self.records.push_back(record); + } +} + +pub struct Handle(Mutex); + +impl Handle { + /// A poisoned lock only means some thread panicked while logging, and the + /// buffer is still fine, so we take it anyway + pub fn lock(&self) -> MutexGuard<'_, Buffer> { + self.0.lock().unwrap_or_else(|poison| poison.into_inner()) + } +} + +static BUFFER: LazyLock = LazyLock::new(|| Handle(Mutex::new(Buffer::default()))); + +/// Messages logged so far. Works before init() too (in tests, for example), +/// where the buffer is just empty +pub fn buffer() -> &'static Handle { + &BUFFER +} + +static FILTER: OnceLock = OnceLock::new(); + +/// Filter in use, shown at the bottom of the log window +pub fn filter() -> &'static str { + FILTER.get().map_or(DEFAULT_FILTER, String::as_str) +} + +/// Puts every message in the buffer the log window reads from +struct RingLayer; + +impl Layer for RingLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + let metadata = event.metadata(); + let mut visitor = MessageVisitor::default(); + event.record(&mut visitor); + + buffer().lock().push(Record { + time: Local::now(), + level: *metadata.level(), + target: metadata.target(), + span: ctx + .event_scope(event) + .and_then(|mut scope| scope.next()) + .map(|span| span.name()), + message: visitor.finish(), + }); + } +} + +/// Turns an event into "message key=value ..." +#[derive(Default)] +struct MessageVisitor { + message: String, + fields: String, +} + +impl MessageVisitor { + fn finish(mut self) -> String { + self.message.push_str(&self.fields); + self.message + } +} + +impl Visit for MessageVisitor { + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + self.message.push_str(value); + } else { + self.record_debug(field, &value); + } + } + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + // fields can come before the message, so we keep them apart and + // join everything in finish(). writing to a String never fails + let _ = if field.name() == "message" { + write!(self.message, "{value:?}") + } else { + write!(self.fields, " {}={value:?}", field.name()) + }; + } +} + +/// What to do with the messages in the buffer when dz6 exits +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +enum Flush { + /// stderr is redirected, so they were already written there + Streamed, + /// stderr is the terminal and the user asked for logs, so print them all + All, + /// stderr is the terminal and nobody asked for anything: only problems + Problems, +} + +#[derive(Clone, Copy)] +pub struct Logging { + flush: Flush, +} + +impl Logging { + /// Prints the messages the log window couldn't show. Call it only when the + /// TUI is not on the screen (that is, after ratatui::restore()) + pub fn flush(&self) { + let lowest = match self.flush { + Flush::Streamed => return, + Flush::All => Level::TRACE, + Flush::Problems => Level::WARN, + }; + + let buffer = buffer().lock(); + let mut records = buffer + .records() + .iter() + .filter(|record| record.level <= lowest) + .peekable(); + + if records.peek().is_none() { + return; + } + + let mut stderr = io::stderr().lock(); + for record in records { + // if stderr is broken there's nowhere to complain about it + let _ = record.write_to(&mut stderr); + } + } +} + +/// Sets up tracing. Call it once, before anything logs +pub fn init() -> Logging { + let requested = env::var(EnvFilter::DEFAULT_ENV).ok(); + let (filter, rejected) = parse_filter(requested.as_deref()); + + // show what the user asked for, not the directives EnvFilter ends up with + let _ = FILTER.set(match requested.as_deref() { + Some(value) if rejected.is_none() => value.to_owned(), + _ => DEFAULT_FILTER.to_owned(), + }); + + // writing to stderr would show up over the TUI, so we only do it when + // stderr goes somewhere else + let streamed = !io::stderr().is_terminal(); + let stderr_layer = streamed.then(|| { + tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_timer(LocalTime) + .with_writer(io::stderr) + }); + + tracing_subscriber::registry() + .with(filter) + .with(RingLayer) + .with(stderr_layer) + .init(); + + if let Some(rejected) = rejected { + warn!( + value = %rejected, + "invalid {}, using {DEFAULT_FILTER:?}", + EnvFilter::DEFAULT_ENV + ); + } + + let flush = if streamed { + Flush::Streamed + } else if requested.is_some() { + Flush::All + } else { + Flush::Problems + }; + + Logging { flush } +} + +/// Builds the filter from RUST_LOG, or uses DEFAULT_FILTER if it's not set or +/// doesn't parse. A bad value is returned so we can warn about it after the +/// subscriber exists +fn parse_filter(requested: Option<&str>) -> (EnvFilter, Option) { + match requested { + None => (EnvFilter::new(DEFAULT_FILTER), None), + Some(value) => match EnvFilter::builder().parse(value) { + Ok(filter) => (filter, None), + Err(_) => (EnvFilter::new(DEFAULT_FILTER), Some(value.to_owned())), + }, + } +} + +#[cfg(test)] +mod tests { + use super::*; + use pretty_assertions::assert_eq; + + fn record(message: &str) -> Record { + Record { + time: Local::now(), + level: Level::INFO, + target: "dz6::tests", + span: None, + message: message.to_string(), + } + } + + #[test] + fn test_buffer_drops_oldest_messages() { + let mut buffer = Buffer::default(); + + for i in 0..CAPACITY + 3 { + buffer.push(record(&i.to_string())); + } + + assert_eq!(buffer.records().len(), CAPACITY); + assert_eq!(buffer.dropped(), 3); + assert_eq!(buffer.records().front().unwrap().message, "3"); + assert_eq!( + buffer.records().back().unwrap().message, + (CAPACITY + 2).to_string() + ); + } + + #[test] + fn test_invalid_rust_log_falls_back() { + // EnvFilter reorders directives, so we compare with a parsed default + let default = EnvFilter::new(DEFAULT_FILTER).to_string(); + + let (filter, rejected) = parse_filter(Some("dz6=definitely_not_a_level")); + + assert_eq!(filter.to_string(), default); + assert_eq!(rejected.as_deref(), Some("dz6=definitely_not_a_level")); + + let (filter, rejected) = parse_filter(Some("dz6::hex=trace")); + + assert_eq!(filter.to_string(), "dz6::hex=trace"); + assert_eq!(rejected, None); + } + + #[test] + fn test_event_becomes_a_record() { + let subscriber = tracing_subscriber::registry().with(RingLayer); + + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("scope"); + let _entered = span.enter(); + tracing::info!(offset = 0x40, "jumped"); + }); + + let buffer = buffer().lock(); + let record = buffer.records().back().expect("event was recorded"); + + assert_eq!(record.message, "jumped offset=64"); + assert_eq!(record.level, Level::INFO); + assert_eq!(record.span, Some("scope")); + assert_eq!(record.target, "dz6::logging::tests"); + } +} diff --git a/src/main.rs b/src/main.rs index fcf2872..43fa9f1 100644 --- a/src/main.rs +++ b/src/main.rs @@ -10,6 +10,7 @@ mod header; mod hex; mod initfile; mod input_history; +mod logging; mod reader; mod ruler; mod text; @@ -17,12 +18,14 @@ mod themes; mod util; mod widgets; -use std::process; +use std::{io, process::ExitCode}; use clap::Parser; -use ratatui::crossterm::event; +use ratatui::{DefaultTerminal, crossterm::event}; +use tracing::{debug, info, warn}; use app::App; +use logging::Logging; /// vim-like hexadecimal editor #[derive(Parser, Debug)] @@ -40,38 +43,81 @@ struct Args { readonly: bool, } -fn main() { +fn main() -> ExitCode { let args = Args::parse(); + let logging = logging::init(); + + // this goes before ratatui::init(), whose hook wraps ours, so the terminal + // is restored first and then we flush the log + install_panic_hook(logging); + + info!( + version = env!("CARGO_PKG_VERSION"), + file = %args.file, + readonly = args.readonly, + "starting" + ); + + let cursor_offset = match util::parse_offset(&args.offset) { + Ok(offset) => offset, + Err(error) => { + warn!(offset = %args.offset, %error, "invalid offset, starting at 0"); + 0 + } + }; + let mut app = App::new(); - let cursor_offset = util::parse_offset(&args.offset).unwrap_or_default(); - app.load_file(&args.file, cursor_offset, args.readonly) - .unwrap_or_else(|e| { - eprintln!("{}: {}", args.file, e); - process::exit(1); - }); + if let Err(error) = app.load_file(&args.file, cursor_offset, args.readonly) { + eprintln!("{}: {}", args.file, error); + return ExitCode::FAILURE; + } app.list_state.select_first(); - - // read init file ignoring errors - let _ = app.read_initfile(); + app.read_initfile(); let mut terminal = ratatui::init(); + let outcome = run(&mut app, &mut terminal); + ratatui::restore(); + + // the TUI is gone, so we can print what the log window couldn't show + logging.flush(); + + if let Err(error) = outcome { + eprintln!("dz6: {}", error); + return ExitCode::FAILURE; + } + ExitCode::SUCCESS +} + +/// Draw, read one event, handle it, until the user quits or something fails +fn run(app: &mut App, terminal: &mut DefaultTerminal) -> io::Result<()> { while app.running { - terminal - .draw(|f| { - update_page_size(&mut app, f.area().height); - app.screen = f.area(); - draw::draw(f, &mut app) - }) - .expect("failed to draw frame"); - - let event = event::read().expect("unable to read event"); - events::handle_events(&mut app, event).expect("unable to read events"); + terminal.draw(|frame| { + update_page_size(app, frame.area().height); + app.screen = frame.area(); + draw::draw(frame, app); + })?; + + let event = event::read()?; + events::handle_events(app, event)?; } - ratatui::restore(); + debug!("quitting"); + + Ok(()) +} + +/// Flushes the log after a panic. The hook set by ratatui::init() restores the +/// terminal and the default one prints the panic, so our messages come last +fn install_panic_hook(logging: Logging) { + let previous = std::panic::take_hook(); + + std::panic::set_hook(Box::new(move |info| { + previous(info); + logging.flush(); + })); } /// Page size is dynamically calculated as: @@ -87,6 +133,13 @@ pub fn update_page_size(app: &mut App, height: u16) { }; if page_size != app.reader.page_current_size { + debug!( + height, + from = app.reader.page_current_size, + to = page_size, + "page size changed" + ); + app.reader.page_current_size = page_size; app.reader.page_end = app.reader.page_start + page_size.wrapping_sub(1); } diff --git a/src/text/events.rs b/src/text/events.rs index 83f9476..4faefcb 100644 --- a/src/text/events.rs +++ b/src/text/events.rs @@ -1,6 +1,7 @@ use std::io::Result; use ratatui::crossterm::event::{KeyCode, KeyEvent, KeyModifiers}; +use tracing::trace; use crate::{app::App, editor::UIState, text}; @@ -20,7 +21,7 @@ pub fn text_mode_events(app: &mut App, key: KeyEvent) -> Result { app.text_view.lines_to_show += 1; } - App::log(app, format!("{:#?}", app.text_view)); + trace!(view = ?app.text_view, "text view scrolled"); } KeyCode::PageUp => { if app.hex_view.offset < app.reader.page_current_size {