···32323333/// Trait for diagnostics classes. This is like a specific error code.
3434///
3535-/// **For implementors:** The [`Display`] implementation, which is the title of each
3636-/// diagnostic message, should use plurals whenever possible, because error reporters
3737-/// may elect to group together multiple labels of the same [`Issue`]
3535+/// **For implementors:** The [`Display`][fmt::Display] implementation, which is the
3636+/// title of each diagnostic message, should use plurals whenever possible, because
3737+/// error reporters may elect to group together multiple labels of the same [`Issue`]
3838pub trait Issue: Default + fmt::Debug + fmt::Display + Clone + Send + Sync {
3939 fn level(&self) -> Level;
4040}
···8383 output
8484 }
85858686- /// Render the diagnostics as a list of log messages suitable for [`log`].
8686+ /// Render the diagnostics as a list of log messages suitable for logging.
8787 pub fn to_logs(&self) -> String {
8888 let mut output = String::new();
8989 LoggingReportHandler
-10
crates/mdbookkit/src/lib.rs
···11-//! Toolkit for [`mdbook`].
22-//!
33-//! This is the lib documentation. If you are looking for the mdBook [preprocessors]
44-//! that this crate provides, visit <https://tonywu6.github.io/mdbookkit/> instead.
55-//!
66-//! At the moment, the sole purpose of this crate is to facilitate easier testing. Most of the APIs
77-//! are not designed for library use and are explicitly NOT stable.
88-//!
99-//! [preprocessors]: https://rust-lang.github.io/mdBook/format/configuration/preprocessors.html
1010-111pub mod book;
122pub mod diagnostics;
133#[cfg(feature = "_testing")]
+144-216
crates/mdbookkit/src/logging.rs
···11+//! Logging facilities.
22+//!
33+//! ## How the ticker system works
44+//!
55+//! The ticker system integrates with [`tracing`].
66+//!
77+//! Use [`ticker!`][crate::ticker] to create a progress ticker backed by a [`tracing::Span`].
88+//! When the span [closes][mod@tracing::span#closing-spans], the ticker is cleared.
99+//!
1010+//! ```
1111+//! # use tracing::Level;
1212+//! # use mdbookkit::ticker;
1313+//! #
1414+//! let ticker = ticker!(Level::INFO, "task-name", count = 63);
1515+//! // ⠋ [parent-span] task-name (0/63) ...
1616+//! ```
1717+//!
1818+//! Use [`ticker_event!`][crate::ticker_event] to flash a message in the specified ticker.
1919+//! The message is backed by a [`tracing::Event`].
2020+//!
2121+//! ```
2222+//! # use tracing::Level;
2323+//! # use mdbookkit::{ticker, ticker_event};
2424+//! # let ticker = ticker!(Level::INFO, "task-name", count = 63);
2525+//! #
2626+//! ticker_event!(&ticker, Level::INFO, "task updated");
2727+//! // ⠋ [parent-span] task-name (0/63) ... task updated
2828+//! ```
2929+//!
3030+//! Use [`ticker_item!`][crate::ticker_item] to add a subtask to the specified ticker,
3131+//! backed by a [`tracing::Span`]. The `item` field provides the displayed name.
3232+//! When the span closes, the item count in the ticker is increased by 1.
3333+//!
3434+//! ```
3535+//! # use tracing::Level;
3636+//! # use mdbookkit::{ticker, ticker_item};
3737+//! # let ticker = ticker!(Level::INFO, "task-name", count = 63);
3838+//! #
3939+//! let item = ticker_item!(&ticker, Level::INFO, "task", item = "item name");
4040+//! // ⠋ [parent-span] task-name (0/63) ... item name
4141+//! drop(item);
4242+//! // ⠋ [parent-span] task-name (1/63) ... item name
4343+//! ```
4444+//!
4545+//! If the application is configured to be in logging mode, these are emitted as regular logs.
4646+//!
4747+//! ```plaintext
4848+//! INFO parent-span:task-name: started
4949+//! INFO parent-span:task-name: task updated
5050+//! INFO parent-span:task-name:task{item="item name"}: started
5151+//! INFO parent-span:task-name:task{item="item name"}: finished
5252+//! INFO parent-span:task-name: finished
5353+//! ```
5454+//!
5555+//! ### Notes
5656+//!
5757+//! This system uses the parent-child relationship between spans and events to known
5858+//! which progress bars to update.
5959+//!
6060+//! Parent spans must be specified explicitly because ticker and item lifecycles are
6161+//! tracked in [`Layer::on_new_span`] and [`Layer::on_close`], during which a parent span
6262+//! may not have been [entered][mod@tracing::span#entering-a-span], resulting in a
6363+//! `ticker_item!` or a `ticker_event!` without a parent.
6464+//!
6565+//! Spans are tracked at open/close instead of enter/exit because spans may enter/exit
6666+//! multiple times, which does not make sense for progress bars.
6767+168use std::{
22- collections::BTreeSet,
33- fmt::Debug,
44- sync::{Arc, LazyLock, mpsc},
55- thread,
66- time::{Duration, Instant},
6969+ fmt::{Debug, Display},
7070+ io::Write,
7171+ sync::{Arc, LazyLock},
772};
87399-use console::{StyledObject, Term};
1010-use indicatif::{HumanDuration, ProgressBar, ProgressDrawTarget, ProgressStyle};
7474+use console::StyledObject;
1175use tap::{Pipe, Tap};
1276use tracing::{
1377 Event, Subscriber,
1478 field::{Field, Visit},
1579 span::{Attributes, Id},
1616- warn,
1780};
1881use tracing_subscriber::{
1982 EnvFilter, Layer,
···25882689use crate::env::{MDBOOK_LOG, is_colored, is_logging, set_colored, set_logging};
27909191+use self::writer::{MultiProgressTicker, MultiProgressWriter};
9292+9393+mod writer;
9494+2895#[doc(hidden)]
2996#[macro_export]
3097macro_rules! branded {
···83150 .without_time()
84151 .with_target(filter.max_level_hint().unwrap_or(options.level) < LevelFilter::INFO)
85152 .with_ansi(is_colored())
8686- .with_writer(|| WRITER.clone())
8787- .with_filter(if TICKER.is_some() {
153153+ .with_writer(|| TICKER.writer())
154154+ .with_filter(if TICKER.is_enabled() {
88155 Some(filter_fn(|metadata| !is_branded!(metadata)))
89156 } else {
90157 None
91158 });
921599393- let ticker = ConsoleLayer.with_filter(if TICKER.is_none() {
160160+ let ticker = TickerLayer.with_filter(if !TICKER.is_enabled() {
94161 Some(filter_fn(|metadata| !metadata.is_event()))
95162 } else {
96163 None
···117184}
118185119186#[macro_export]
120120-macro_rules! timer {
187187+macro_rules! ticker {
121188 ( $level:expr, $key:literal, $( $span:tt )* ) => {
122189 ::tracing::span!(
123190 $level,
124191 $key,
125125- { $crate::branded!("timer") } = ::tracing::field::Empty,
192192+ { $crate::branded!("ticker") } = ::tracing::field::Empty,
126193 $($span)*
127194 )
128195 };
129196 ( $level:expr, $key:literal ) => {
130130- $crate::timer!($level, $key,)
197197+ $crate::ticker!($level, $key,)
131198 }
132199}
133200134201#[macro_export]
135135-macro_rules! timer_event {
202202+macro_rules! ticker_event {
136203 ( $parent:expr, $level:expr, $( $span:tt )* ) => {
137204 ::tracing::event!(
138205 parent: $parent,
139206 $level,
140140- { $crate::branded!("timer.event") } = ::tracing::field::Empty,
207207+ { $crate::branded!("ticker.event") } = ::tracing::field::Empty,
141208 $($span)*
142209 )
143210 };
144211 ( $parent:expr, $level:expr ) => {
145145- $crate::timer_event!($parent, $level,)
212212+ $crate::ticker_event!($parent, $level,)
146213 }
147214}
148215149216#[macro_export]
150150-macro_rules! timer_item {
217217+macro_rules! ticker_item {
151218 ( $parent:expr, $level:expr, $key:literal, $( $span:tt )* ) => {
152219 ::tracing::span!(
153220 parent: $parent,
154221 $level,
155222 $key,
156156- { $crate::branded!("timer.item") } = ::tracing::field::Empty,
223223+ { $crate::branded!("ticker.item") } = ::tracing::field::Empty,
157224 $($span)*
158225 )
159226 };
160227 ( $parent:expr, $level:expr, $key:literal ) => {
161161- $crate::timer_item!($parent, $level, $key,)
228228+ $crate::ticker_item!($parent, $level, $key,)
162229 }
163230}
164231165165-struct ConsoleLayer;
232232+struct TickerLayer;
166233167167-impl<S> Layer<S> for ConsoleLayer
234234+impl<S> Layer<S> for TickerLayer
168235where
169236 S: Subscriber + for<'a> LookupSpan<'a>,
170237{
171238 fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
172239 let Some(span) = ctx.span(id) else { return };
173240174174- if is_branded!(span, "timer") {
175175- let TimerVisitor { count, .. } = TimerVisitor::from_attrs(attrs);
241241+ if is_branded!(span, "ticker") {
242242+ let TickerVisitor { count, .. } = TickerVisitor::from_attrs(attrs);
176243177177- let timer = Timer {
244244+ let ticker = TickerData {
178245 prefix: SpanPath::to_string(&span),
179246 key: span.name(),
180247 count,
181248 };
182249183183- span.extensions_mut().insert(timer.clone());
250250+ span.extensions_mut().insert(ticker.clone());
184251185185- if let Some(ticker) = &*TICKER {
186186- (ticker.tx).send(ProgressTick::TimerCreate(timer)).ok();
252252+ if let Some(tx) = TICKER.sender() {
253253+ tx.send(ProgressTick::TickerCreate(ticker)).ok();
187254 } else {
188255 derive_event!(id, span.metadata(), "message" = "started");
189256 }
190190- } else if is_branded!(span, "timer.item")
191191- && let TimerVisitor {
257257+ } else if is_branded!(span, "ticker.item")
258258+ && let TickerVisitor {
192259 item: Some(item), ..
193193- } = TimerVisitor::from_attrs(attrs)
260260+ } = TickerVisitor::from_attrs(attrs)
194261 && let Some(parent) = span.parent()
195195- && let Some(Timer { key, .. }) = parent.extensions().get::<Timer>()
262262+ && let Some(TickerData { key, .. }) = parent.extensions().get::<TickerData>()
196263 {
197197- span.extensions_mut().insert(TimerItem(item.clone()));
264264+ span.extensions_mut().insert(TickerItem(item.clone()));
198265199199- if let Some(ticker) = &*TICKER {
200200- (ticker.tx).send(ProgressTick::ItemOpen { key, item }).ok();
266266+ if let Some(tx) = TICKER.sender() {
267267+ tx.send(ProgressTick::ItemOpen { key, item }).ok();
201268 } else {
202269 derive_event!(id, span.metadata(), "message" = "started");
203270 }
···210277 // n.b. using extensions_mut involves a RwLock write, which will cause
211278 // derive_event to deadlock when it tries to read from the same span
212279213213- if let Some(Timer { key, .. }) = span.extensions().get::<Timer>() {
214214- if let Some(ticker) = &*TICKER {
215215- ticker.tx.send(ProgressTick::TimerFinish { key }).ok();
280280+ if let Some(TickerData { key, .. }) = span.extensions().get::<TickerData>() {
281281+ if let Some(tx) = TICKER.sender() {
282282+ tx.send(ProgressTick::TickerFinish { key }).ok();
216283 } else {
217284 derive_event!(id, span.metadata(), "message" = "finished");
218285 }
219286 } else if let Some(parent) = span.parent()
220220- && let Some(Timer { key, .. }) = parent.extensions().get::<Timer>()
221221- && let Some(TimerItem(item)) = span.extensions().get::<TimerItem>()
287287+ && let Some(TickerData { key, .. }) = parent.extensions().get::<TickerData>()
288288+ && let Some(TickerItem(item)) = span.extensions().get::<TickerItem>()
222289 {
223223- if let Some(ticker) = &*TICKER {
290290+ if let Some(tx) = TICKER.sender() {
224291 let item = item.clone();
225225- (ticker.tx).send(ProgressTick::ItemDone { key, item }).ok();
292292+ tx.send(ProgressTick::ItemDone { key, item }).ok();
226293 } else {
227294 derive_event!(id, span.metadata(), "message" = "finished");
228295 }
···234301 return;
235302 }
236303237237- if let TimerVisitor {
304304+ if let TickerVisitor {
238305 message: Some(msg), ..
239239- } = TimerVisitor::from_event(event)
306306+ } = TickerVisitor::from_event(event)
240307 && let Some(span) = (event.parent().cloned())
241308 .or_else(|| ctx.current_span().id().cloned())
242309 .and_then(|id| ctx.span(&id))
243243- && let Some(Timer { key, .. }) = span.extensions().get::<Timer>()
310310+ && let Some(TickerData { key, .. }) = span.extensions().get::<TickerData>()
244311 {
245245- if let Some(ticker) = &*TICKER {
246246- (ticker.tx)
247247- .send(ProgressTick::TimerUpdate { key, msg })
248248- .ok();
312312+ if let Some(tx) = TICKER.sender() {
313313+ tx.send(ProgressTick::TickerUpdate { key, msg }).ok();
249314 }
250315 }
251316 }
252317}
253318254319#[derive(Debug, Default)]
255255-struct TimerVisitor {
320320+struct TickerVisitor {
256321 message: Option<String>,
257322 item: Option<Arc<str>>,
258323 count: Option<u64>,
259324}
260325261261-impl Visit for TimerVisitor {
326326+impl Visit for TickerVisitor {
262327 fn record_str(&mut self, field: &Field, value: &str) {
263328 match field.name() {
264329 "message" => self.message = Some(value.into()),
···278343 }
279344}
280345281281-impl TimerVisitor {
346346+impl TickerVisitor {
282347 #[inline]
283348 fn from_attrs(attrs: &Attributes<'_>) -> Self {
284349 Self::default().tap_mut(|v| attrs.values().record(v))
···319384}
320385321386#[derive(Debug, Clone)]
322322-struct Timer {
387387+struct TickerData {
323388 prefix: Option<Arc<str>>,
324389 key: &'static str,
325390 count: Option<u64>,
326391}
327392328328-impl std::fmt::Display for Timer {
393393+impl Display for TickerData {
329394 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
330395 if let Some(ref prefix) = self.prefix {
331396 write!(f, "[{prefix}] {}", self.key)
···336401}
337402338403#[derive(Debug, Clone)]
339339-struct TimerItem(Arc<str>);
404404+struct TickerItem(Arc<str>);
340405341406#[derive(Debug)]
342407enum ProgressTick {
343343- TimerCreate(Timer),
344344- TimerUpdate { key: &'static str, msg: String },
408408+ TickerCreate(TickerData),
409409+ TickerUpdate { key: &'static str, msg: String },
345410 ItemOpen { key: &'static str, item: Arc<str> },
346411 ItemDone { key: &'static str, item: Arc<str> },
347347- TimerFinish { key: &'static str },
348348-}
349349-350350-#[derive(Clone)]
351351-struct ProgressTicker {
352352- tx: mpsc::Sender<ProgressTick>,
412412+ TickerFinish { key: &'static str },
353413}
354414355355-static WRITER: LazyLock<Term> = LazyLock::new(Term::stderr);
356356-357357-static TICKER: LazyLock<Option<ProgressTicker>> = LazyLock::new(|| {
358358- if is_logging() {
359359- None
360360- } else {
361361- Some(spawn_ticker())
362362- }
363363-});
364364-365365-fn spawn_ticker() -> ProgressTicker {
366366- let (tx, rx) = mpsc::channel();
367367-368368- let style = ProgressStyle::with_template("{spinner:.cyan} {prefix} ... {msg}")
369369- .unwrap()
370370- .tick_chars("⠇⠋⠙⠸⠴⠦⠿");
371371-372372- thread::spawn(move || {
373373- struct Bar {
374374- timer: Timer,
375375- bar: ProgressBar,
376376- }
377377-378378- impl Bar {
379379- fn count(&self) {
380380- let Self { timer, bar } = self;
381381- if let Some(length) = bar.length() {
382382- let counter = styled(format!("({}/{length})", bar.position())).dim();
383383- bar.set_prefix(format!("{timer} {counter}"))
384384- }
385385- }
386386- }
387387-388388- let mut current: Option<Bar> = None;
389389-390390- let mut tasks = BTreeSet::new();
391391- let mut task_idx = 0;
392392- let mut interval = Instant::now();
393393-394394- loop {
395395- let current_ref = |key: &str| {
396396- let bar = current.as_ref()?;
397397- if bar.timer.key == key {
398398- Some(bar)
399399- } else {
400400- None
401401- }
402402- };
403403-404404- match rx.recv_timeout(Duration::from_millis(100)) {
405405- Err(mpsc::RecvTimeoutError::Timeout) => {}
406406-407407- Err(mpsc::RecvTimeoutError::Disconnected) => break,
408408-409409- Ok(ProgressTick::TimerCreate(timer)) => {
410410- if let Some(bar) = current {
411411- bar.bar.abandon()
412412- }
413413-414414- let bar = ProgressDrawTarget::term(WRITER.clone(), 20)
415415- .pipe(|target| ProgressBar::with_draw_target(timer.count, target))
416416- .with_prefix(timer.to_string())
417417- .with_style(style.clone());
418418-419419- bar.enable_steady_tick(Duration::from_millis(100));
420420-421421- current = Some(Bar { timer, bar });
422422- }
423423-424424- Ok(ProgressTick::TimerUpdate { key, msg }) => {
425425- let Some(Bar { bar, .. }) = current_ref(key) else {
426426- continue;
427427- };
428428-429429- bar.set_message(msg);
430430- bar.tick();
431431- }
432432-433433- Ok(ProgressTick::TimerFinish { key }) => {
434434- let Some(Bar { bar, .. }) = current_ref(key) else {
435435- continue;
436436- };
437437-438438- bar.finish_with_message(styled("done").green().to_string());
439439- current = None;
440440- }
441441-442442- Ok(ProgressTick::ItemOpen { key, item }) => {
443443- let Some(current) = current_ref(key) else {
444444- continue;
445445- };
446446-447447- current.count();
448448- current.bar.set_message(styled(&item).magenta().to_string());
449449- current.bar.tick();
450450-451451- tasks.insert(item);
452452- interval = Instant::now();
453453- }
454454-455455- Ok(ProgressTick::ItemDone { key, item }) => {
456456- let Some(current) = current_ref(key) else {
457457- continue;
458458- };
459459-460460- current.bar.inc(1);
461461-462462- current.count();
463463- current.bar.set_message(styled(&item).green().to_string());
464464- current.bar.tick();
465465-466466- tasks.remove(&item);
467467- interval = Instant::now();
468468- }
469469- }
470470-471471- if let Some(Bar {
472472- timer: Timer { key, .. },
473473- ref bar,
474474- ..
475475- }) = current
476476- {
477477- let now = Instant::now();
478478-479479- if now - interval > Duration::from_secs(10) {
480480- interval = now;
481481-482482- if task_idx >= tasks.len() {
483483- task_idx = 0
484484- }
485485-486486- if let Some(task) = tasks.iter().nth(task_idx) {
487487- let elapsed = HumanDuration(bar.elapsed());
488488- // TODO: how to attach to current span
489489- // TODO: how to clear line for tracing when ticker is running
490490- warn!("task {key} - {task} has been running for more than {elapsed}");
491491- bar.set_message(styled(task).magenta().to_string());
492492- task_idx += 1;
493493- }
494494- }
495495- }
496496- }
497497- });
498498-499499- ProgressTicker { tx }
500500-}
415415+static TICKER: LazyLock<MultiProgressTicker> =
416416+ LazyLock::new(|| MultiProgressWriter::new(!is_logging()).pipe(MultiProgressTicker::new));
501417502418#[inline]
503503-pub fn stderr() -> impl std::io::Write {
504504- WRITER.clone()
419419+pub fn stderr() -> impl Write {
420420+ TICKER.writer()
505421}
506422507507-// FIXME: ensure colors do not appear in tracing output
508508-// https://github.com/tokio-rs/tracing/issues/3378
423423+/// Configure styling for a displayable value.
424424+///
425425+/// ## Note
426426+///
427427+/// Avoid using this in tracing messages.
428428+///
429429+/// tracing-subscriber currently escapes all ANSI characters.
430430+/// See <https://github.com/tokio-rs/tracing/issues/3378>
431431+///
432432+/// This function disables styling if the application is in logging mode, so that
433433+/// messages can have styling in tickers but not in logs.
509434#[inline]
510435pub fn styled<D>(val: D) -> StyledObject<D> {
511511- WRITER.style().apply_to(val)
436436+ let styled = TICKER.style().apply_to(val);
437437+ if TICKER.is_enabled() {
438438+ styled
439439+ } else {
440440+ styled.force_styling(false)
441441+ }
512442}
513443514444#[macro_export]
···546476 |e| ::tracing::warn!($fmt, e)
547477 };
548478}
549549-550550-// TODO: clean up logging messages & make use of spans/instrument
···1010/// as much of the original Markdown source as possible, especially with regard to whitespace.
1111///
1212/// Currently, when using [`pulldown_cmark_to_cmark`] to generate Markdown from a
1313-/// [`pulldown_cmark::Event`] stream, whitespace is NOT preserved. This is problematic
1313+/// [`pulldown_cmark::Event`][Event] stream, whitespace is NOT preserved. This is problematic
1414/// for mdBook preprocessors, because preprocessors downstream may need to work on
1515/// syntax that is whitespace-sensitive. Normalizing all whitespace could cause such
1616/// usage to no longer be recognized.