cu_profiler_core/parser/
solana_logs.rs

1//! Tolerant lexer for Solana program logs.
2//!
3//! The lexer turns raw log lines into a flat stream of [`LogEvent`]s. It never
4//! panics on malformed input: a line it cannot classify is preserved as
5//! [`LogEvent::Raw`], and a line that looks structured but parses badly yields a
6//! [`LogEvent::Raw`] plus an actionable warning, lowering confidence downstream.
7
8use crate::parser::scope_markers::{self, MarkerKind};
9
10/// One recognised (or preserved) log line.
11#[derive(Debug, Clone, PartialEq, Eq)]
12pub enum LogEvent {
13    /// `Program <id> invoke [<depth>]`
14    Invoke {
15        /// Program being invoked.
16        program_id: String,
17        /// Invoke depth (1 for the top level).
18        depth: u32,
19    },
20    /// `Program <id> consumed <used> of <budget> compute units`
21    Consumed {
22        /// Program reporting consumption.
23        program_id: String,
24        /// CU consumed by this invocation.
25        used: u64,
26        /// CU budget available to this invocation.
27        budget: u64,
28    },
29    /// `Program <id> success`
30    Success {
31        /// Program that succeeded.
32        program_id: String,
33    },
34    /// `Program <id> failed: <reason>` (or `Program failed to complete`).
35    Failed {
36        /// Program that failed (may be empty if the runtime didn't name it).
37        program_id: String,
38        /// Failure reason.
39        reason: String,
40    },
41    /// A `Program log:` message that is not a profiler marker.
42    Log {
43        /// The message text.
44        message: String,
45    },
46    /// A balanced-scope begin marker.
47    ScopeBegin {
48        /// Scope name.
49        name: String,
50        /// Remaining compute units at the marker, if logged.
51        cu: Option<u64>,
52    },
53    /// A scope end marker.
54    ScopeEnd {
55        /// Scope name.
56        name: String,
57        /// Remaining compute units at the marker, if logged.
58        cu: Option<u64>,
59    },
60    /// A point-in-time marker.
61    ScopePoint {
62        /// Marker name.
63        name: String,
64        /// Remaining compute units at the marker, if logged.
65        cu: Option<u64>,
66    },
67    /// Any line that could not be classified, preserved verbatim.
68    Raw(String),
69}
70
71/// The outcome of lexing a log stream.
72#[derive(Debug, Default, Clone)]
73pub struct LexResult {
74    /// Recognised events, each tagged with its source line index.
75    pub events: Vec<(usize, LogEvent)>,
76    /// Non-fatal warnings (malformed-but-recoverable lines).
77    pub warnings: Vec<String>,
78}
79
80impl LexResult {
81    /// Iterate over just the events, dropping line indices.
82    pub fn events(&self) -> impl Iterator<Item = &LogEvent> {
83        self.events.iter().map(|(_, e)| e)
84    }
85}
86
87/// Lex a slice of log lines into a [`LexResult`].
88#[must_use]
89pub fn lex(lines: &[String]) -> LexResult {
90    let mut result = LexResult::default();
91    for (index, raw) in lines.iter().enumerate() {
92        let line = raw.trim();
93        if line.is_empty() {
94            continue;
95        }
96        match classify(line, index) {
97            Ok(event) => result.events.push((index, event)),
98            Err(warning) => {
99                result.warnings.push(warning);
100                result.events.push((index, LogEvent::Raw(raw.clone())));
101            }
102        }
103    }
104    result
105}
106
107/// Classify a single trimmed line. `Err` carries an actionable warning string;
108/// the caller preserves the original line as [`LogEvent::Raw`].
109fn classify(line: &str, index: usize) -> Result<LogEvent, String> {
110    if let Some(rest) = line.strip_prefix("Program log: ") {
111        return Ok(classify_log_message(rest));
112    }
113    if let Some(rest) = line.strip_prefix("Program data: ") {
114        return Ok(LogEvent::Log {
115            message: format!("data: {rest}"),
116        });
117    }
118    if line == "Program failed to complete" {
119        return Ok(LogEvent::Failed {
120            program_id: String::new(),
121            reason: "failed to complete".to_string(),
122        });
123    }
124    if let Some(rest) = line.strip_prefix("Program ") {
125        return classify_program_line(rest, index);
126    }
127    Ok(LogEvent::Raw(line.to_string()))
128}
129
130/// Handle a `Program log:` payload, detecting profiler markers.
131fn classify_log_message(message: &str) -> LogEvent {
132    match scope_markers::parse_marker(message) {
133        Some(m) => match m.kind {
134            MarkerKind::Begin => LogEvent::ScopeBegin {
135                name: m.name,
136                cu: m.cu,
137            },
138            MarkerKind::End => LogEvent::ScopeEnd {
139                name: m.name,
140                cu: m.cu,
141            },
142            MarkerKind::Point => LogEvent::ScopePoint {
143                name: m.name,
144                cu: m.cu,
145            },
146        },
147        None => LogEvent::Log {
148            message: message.to_string(),
149        },
150    }
151}
152
153/// Handle the portion of a line after the leading `Program `.
154fn classify_program_line(rest: &str, index: usize) -> Result<LogEvent, String> {
155    // `<id> invoke [<depth>]`
156    if let Some((id, tail)) = rest.split_once(" invoke ") {
157        let depth = tail
158            .trim()
159            .trim_start_matches('[')
160            .trim_end_matches(']')
161            .parse::<u32>()
162            .map_err(|_| {
163                format!(
164                    "failed to parse invoke depth at log index {index}: expected `[<n>]`, got `{tail}`"
165                )
166            })?;
167        return Ok(LogEvent::Invoke {
168            program_id: id.to_string(),
169            depth,
170        });
171    }
172
173    // `<id> consumed <used> of <budget> compute units`
174    if let Some((id, tail)) = rest.split_once(" consumed ") {
175        return parse_consumed(id, tail, index).map_err(|e| e.to_string());
176    }
177
178    // `<id> success`
179    if let Some(id) = rest.strip_suffix(" success") {
180        return Ok(LogEvent::Success {
181            program_id: id.to_string(),
182        });
183    }
184
185    // `<id> failed: <reason>`
186    if let Some((id, reason)) = rest.split_once(" failed: ") {
187        return Ok(LogEvent::Failed {
188            program_id: id.to_string(),
189            reason: reason.to_string(),
190        });
191    }
192    if let Some(id) = rest.strip_suffix(" failed") {
193        return Ok(LogEvent::Failed {
194            program_id: id.to_string(),
195            reason: "failed".to_string(),
196        });
197    }
198
199    Ok(LogEvent::Raw(format!("Program {rest}")))
200}
201
202/// Parse the `<used> of <budget> compute units` tail. Returns a typed
203/// [`crate::Error`] with the precise reason on malformed numerics.
204fn parse_consumed(id: &str, tail: &str, index: usize) -> crate::Result<LogEvent> {
205    let body = tail.strip_suffix(" compute units").unwrap_or(tail).trim();
206    let (used_s, budget_s) = body.split_once(" of ").ok_or_else(|| {
207        crate::Error::parse(
208            "compute-unit line",
209            index,
210            format!("expected `<used> of <budget> compute units`, got `{tail}`"),
211        )
212    })?;
213    let used = used_s.trim().replace(',', "").parse::<u64>().map_err(|_| {
214        crate::Error::parse(
215            "compute-unit line",
216            index,
217            format!("expected integer for consumed units, got `{used_s}`"),
218        )
219    })?;
220    let budget = budget_s
221        .trim()
222        .replace(',', "")
223        .parse::<u64>()
224        .map_err(|_| {
225            crate::Error::parse(
226                "compute-unit line",
227                index,
228                format!("expected integer for unit budget, got `{budget_s}`"),
229            )
230        })?;
231    Ok(LogEvent::Consumed {
232        program_id: id.to_string(),
233        used,
234        budget,
235    })
236}
237
238#[cfg(test)]
239mod tests {
240    use super::*;
241
242    #[test]
243    fn parses_invoke_consumed_success() {
244        let lines = vec![
245            "Program Vote111 invoke [1]".to_string(),
246            "Program Vote111 consumed 1200 of 200000 compute units".to_string(),
247            "Program Vote111 success".to_string(),
248        ];
249        let r = lex(&lines);
250        assert!(r.warnings.is_empty());
251        assert_eq!(
252            r.events[0].1,
253            LogEvent::Invoke {
254                program_id: "Vote111".into(),
255                depth: 1
256            }
257        );
258        assert_eq!(
259            r.events[1].1,
260            LogEvent::Consumed {
261                program_id: "Vote111".into(),
262                used: 1200,
263                budget: 200000
264            }
265        );
266        assert_eq!(
267            r.events[2].1,
268            LogEvent::Success {
269                program_id: "Vote111".into()
270            }
271        );
272    }
273
274    #[test]
275    fn unknown_lines_are_preserved_not_panicked() {
276        let lines = vec!["totally unexpected line".to_string()];
277        let r = lex(&lines);
278        assert_eq!(
279            r.events[0].1,
280            LogEvent::Raw("totally unexpected line".into())
281        );
282        assert!(r.warnings.is_empty());
283    }
284
285    #[test]
286    fn malformed_consumed_warns_and_keeps_raw() {
287        let lines = vec!["Program X consumed abc of 200000 compute units".to_string()];
288        let r = lex(&lines);
289        assert_eq!(r.warnings.len(), 1);
290        assert!(r.warnings[0].contains("expected integer for consumed units"));
291        assert!(matches!(r.events[0].1, LogEvent::Raw(_)));
292    }
293
294    #[test]
295    fn detects_failure_with_reason() {
296        let lines = vec!["Program X failed: custom program error: 0x1".to_string()];
297        let r = lex(&lines);
298        assert_eq!(
299            r.events[0].1,
300            LogEvent::Failed {
301                program_id: "X".into(),
302                reason: "custom program error: 0x1".into()
303            }
304        );
305    }
306
307    #[test]
308    fn detects_scope_markers_in_log_messages() {
309        let lines = vec![
310            "Program log: CU_PROFILER_BEGIN name=swap::validate cu=200000".to_string(),
311            "Program log: hello".to_string(),
312            "Program log: CU_PROFILER_END name=swap::validate cu=195000".to_string(),
313        ];
314        let r = lex(&lines);
315        assert_eq!(
316            r.events[0].1,
317            LogEvent::ScopeBegin {
318                name: "swap::validate".into(),
319                cu: Some(200_000),
320            }
321        );
322        assert!(matches!(r.events[1].1, LogEvent::Log { .. }));
323        assert_eq!(
324            r.events[2].1,
325            LogEvent::ScopeEnd {
326                name: "swap::validate".into(),
327                cu: Some(195_000),
328            }
329        );
330    }
331}
cu_profiler_core/parser/solana_logs.rs

cu_profiler_core/parser/
solana_logs.rs
