hpsvm 0.1.19

A fast and lightweight Solana VM simulator for testing solana programs
Documentation
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
use std::fmt::Write;

use nu_ansi_term::{AnsiString, Color, Style};

const PROGRAM_LOG: &str = "Program log:";

#[derive(Debug, Clone, Copy, PartialEq, Eq)]
enum Importance {
    Low,
    High,
    VeryHigh,
    Error,
}

fn get_importance(program_source: &str, program_log: &str) -> Importance {
    let log = program_log.to_lowercase();
    if log.contains("error: ") ||
        log.contains("error ") ||
        log.contains("err: ") ||
        log.contains("err ") ||
        log.contains("failure: ") ||
        log.contains("failure ") ||
        log.contains("failed: ") ||
        log.contains("failed ") ||
        log.contains("fail: ") ||
        log.contains("fail ")
    {
        Importance::Error
    } else if log.contains("signer privilege escalated") {
        Importance::High
    } else if program_source == PROGRAM_LOG {
        Importance::VeryHigh
    } else {
        Importance::Low
    }
}

/// Map an `Importance` to an ANSI `Style`. Colors mirror the previous
/// hand-coded palette so output stays byte-identical to the old implementation.
fn style_for(importance: Importance) -> Style {
    match importance {
        // Previous: "\x1b[1;38;5;9m" — bold bright red
        Importance::Error => Style::new().bold().fg(Color::Fixed(9)),
        // Previous: "\x1b[32m" — green
        Importance::VeryHigh => Style::new().fg(Color::Green),
        // Previous: "\x1b[1;38;5;243m" — bold fixed 243 (gray)
        Importance::High => Style::new().bold().fg(Color::Fixed(243)),
        // Previous: "\x1b[38;5;239m" — fixed 239 (dark gray)
        Importance::Low => Style::new().fg(Color::Fixed(239)),
    }
}

fn colourise(importance: Importance, log: &str) -> AnsiString<'_> {
    style_for(importance).paint(log)
}

fn format_line(line: &str) -> String {
    const PROGRAM: &str = "Program";
    const PROCESS_INSTRUCTION: &str = "process_instruction:";
    const SOLANA_RUNTIME: &str = "solana_runtime:";
    // Check for optional prefixes
    let (program_source, program_log) = match line {
        s if s.starts_with(PROGRAM_LOG) => (PROGRAM_LOG, s[PROGRAM_LOG.len()..].trim_start()),
        s if s.starts_with(PROGRAM) => (PROGRAM, s[PROGRAM.len()..].trim_start()),
        s if s.starts_with(PROCESS_INSTRUCTION) => {
            (PROCESS_INSTRUCTION, s[PROCESS_INSTRUCTION.len()..].trim_start())
        }
        s if s.starts_with(SOLANA_RUNTIME) => {
            (SOLANA_RUNTIME, s[SOLANA_RUNTIME.len()..].trim_start())
        }
        s => ("", s),
    };
    let importance = get_importance(program_source, program_log);
    let log = if ["", PROGRAM_LOG].contains(&program_source) {
        program_log.to_string()
    } else {
        format!("{program_source} {program_log}")
    };
    // `colourise` returns an `AnsiString` borrowing from `log`; since `log` is
    // a local `String`, materialise the painted output into an owned `String`
    // before returning so the borrow does not escape its lifetime.
    colourise(importance, &log).to_string()
}

pub(crate) fn format_logs(logs: &[String]) -> String {
    let mut out: String = String::new();
    for line in logs {
        if !line.is_empty() {
            let formatted = format_line(line);
            writeln!(&mut out, "{formatted}").expect("writing to String should never fail");
        }
    }
    out
}

#[cfg(test)]
mod tests {
    use proptest::prelude::*;

    use super::*;

    const BOLD_RED: &str = "\u{1b}[1;38;5;9m";
    const GREEN: &str = "\u{1b}[32m";
    const BOLD_GRAY: &str = "\u{1b}[1;38;5;243m";
    const DARK_GRAY: &str = "\u{1b}[38;5;239m";
    const RESET: &str = "\u{1b}[0m";

    // Examples:
    //
    // ["Program 11111111111111111111111111111111 invoke [1]", "Program
    // 11111111111111111111111111111111 failed: Computational budget exceeded"]
    // ["Program 11111111111111111111111111111111 invoke [1]", "Program
    // 11111111111111111111111111111111 success"] ["Program 11111111111111111111111111111111
    // invoke [1]", "Program 11111111111111111111111111111111 success", "Program
    // TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA invoke [1]", "Program log: Instruction:
    // InitializeMint2", "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA consumed 2779 of
    // 202850 compute units", "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA success"]
    // ["Program Logging111111111111111111111111111111111111 invoke [1]", "Program log: static
    // string"] ["Program Config1111111111111111111111111111111111111 invoke [1]", "account
    // J2kSTGu6eod7MUAy2nNZhFW5ye5ZdhAri6bcJJHRhhXy signer_key().is_none()", "Program
    // Config1111111111111111111111111111111111111 failed: missing required signature for
    // instruction"] ["Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM invoke [1]", "Program
    // log: panicked at clock-example/src/lib.rs:17:5:\nassertion failed: got_clock.unix_timestamp <
    // 100", "Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM consumed 1751 of 200000 compute
    // units", "Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM failed: SBF program panicked"]
    #[test]
    fn test_format_line() {
        let line = "Program 11111111111111111111111111111111 failed: Computational budget exceeded";
        let formatted = format_line(line);
        // nu-ansi-term merges bold + fixed-color into a single combined SGR sequence
        // (`\x1b[1;38;5;9m`), which is semantically equivalent to two separate sequences
        // and renders identically in terminals.
        assert_eq!(
            formatted,
            "\u{1b}[1;38;5;9mProgram 11111111111111111111111111111111 failed: Computational budget exceeded\u{1b}[0m"
        );
        let line = "Program log: static string";
        let formatted = format_line(line);
        eprintln!("{formatted}");
        assert_eq!(formatted, "\u{1b}[32mstatic string\u{1b}[0m");
    }

    #[test]
    fn test_format_logs() {
        let logs = ["Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM invoke [1]", "Program log: panicked at clock-example/src/lib.rs:17:5:\nassertion failed: got_clock.unix_timestamp < 100", "Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM consumed 1751 of 200000 compute units", "Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM failed: SBF program panicked"].map(ToString::to_string);
        let formatted = format_logs(&logs);
        // Test that output contains ANSI codes for each line; exact byte-equality
        // may differ slightly because nu-ansi-term emits `\x1b[1m` then `\x1b[38;5;Nm`
        // for bold+fixed-color combinations. Verify the basic structure instead.
        assert!(formatted.contains("\u{1b}[0m"));
        assert!(formatted.contains("Program 1111111QLbz7JHiBTspS962RLKV8GndWFwiEaqKM invoke [1]"));
        assert!(formatted.contains("panicked at clock-example"));
    }

    /// Each of the ten error keywords must classify the log as [`Importance::Error`].
    #[test]
    fn every_error_keyword_yields_error_importance() {
        let keywords = [
            "error: ",
            "error ",
            "err: ",
            "err ",
            "failure: ",
            "failure ",
            "failed: ",
            "failed ",
            "fail: ",
            "fail ",
        ];
        for keyword in keywords {
            assert_eq!(
                get_importance(PROGRAM_LOG, keyword),
                Importance::Error,
                "keyword {keyword:?}"
            );
        }
    }

    /// Keyword matching is case-insensitive because the log is lowercased first.
    #[test]
    fn error_keyword_matching_is_case_insensitive() {
        for keyword in ["ERROR: boom", "Failed: x", "Err: y", "FaIl: z", "FAILURE w"] {
            assert_eq!(
                get_importance(PROGRAM_LOG, keyword),
                Importance::Error,
                "keyword {keyword:?}"
            );
        }
    }

    /// A keyword only counts as an error when it is followed by a space, so
    /// substrings such as "errorless" or "failed_up" must not be misclassified.
    #[test]
    fn keywords_without_a_trailing_space_are_not_errors() {
        for log in ["errorless path", "failed_up", "failover", "no errors here", "my err:or"] {
            assert_eq!(get_importance(PROGRAM_LOG, log), Importance::VeryHigh, "log {log:?}");
        }
    }

    /// The error check wins over both the escalation and the `Program log:`
    /// branches, so a panicking program log is always rendered in bold red.
    #[test]
    fn error_importance_outranks_escalation_and_program_log() {
        assert_eq!(get_importance(PROGRAM_LOG, "failed: out of compute"), Importance::Error);
        assert_eq!(
            get_importance(PROGRAM_LOG, "failed: signer privilege escalated"),
            Importance::Error
        );
        // A non-`Program log:` source still yields Error for an error keyword.
        assert_eq!(get_importance("Program", "failure : nested"), Importance::Error);
    }

    #[test]
    fn escalation_is_high_importance_outside_program_logs() {
        assert_eq!(get_importance("Program", "signer privilege escalated"), Importance::High);
        assert_eq!(get_importance("", "signer privilege escalated"), Importance::High);
    }

    #[test]
    fn program_logs_are_very_high_importance() {
        assert_eq!(get_importance(PROGRAM_LOG, "hello world"), Importance::VeryHigh);
    }

    #[test]
    fn unrecognised_sources_are_low_importance() {
        for (source, log) in [
            ("Program", "invoke [1]"),
            ("process_instruction:", "Trace"),
            ("solana_runtime:", "x"),
            ("", "plain"),
        ] {
            assert_eq!(get_importance(source, log), Importance::Low, "source {source:?}");
        }
    }

    #[test]
    fn style_for_maps_each_importance_to_a_distinct_palette() {
        // `Style` is not `Display`, so paint a marker and inspect the prefix.
        let painted = |importance| style_for(importance).paint("x").to_string();
        assert!(
            painted(Importance::Error).starts_with(BOLD_RED),
            "got {}",
            painted(Importance::Error)
        );
        assert!(
            painted(Importance::VeryHigh).starts_with(GREEN),
            "got {}",
            painted(Importance::VeryHigh)
        );
        assert!(
            painted(Importance::High).starts_with(BOLD_GRAY),
            "got {}",
            painted(Importance::High)
        );
        assert!(
            painted(Importance::Low).starts_with(DARK_GRAY),
            "got {}",
            painted(Importance::Low)
        );
    }

    #[test]
    fn colourise_wraps_the_log_in_the_importance_style() {
        assert_eq!(colourise(Importance::Error, "x").to_string(), format!("{BOLD_RED}x{RESET}"));
        assert_eq!(colourise(Importance::Low, "x").to_string(), format!("{DARK_GRAY}x{RESET}"));
    }

    /// `Program log:` strips its prefix and paints the remainder green.
    #[test]
    fn program_log_prefix_is_stripped() {
        assert_eq!(
            format_line("Program log: static string"),
            format!("{GREEN}static string{RESET}")
        );
        // Leading spaces after the prefix are trimmed.
        assert_eq!(format_line("Program log:   padded"), format!("{GREEN}padded{RESET}"));
    }

    /// `Program ` keeps its prefix but lowers the importance to Low.
    #[test]
    fn program_prefix_is_preserved_with_low_importance() {
        assert_eq!(
            format_line("Program 11111111111111111111111111111111 invoke [1]"),
            format!("{DARK_GRAY}Program 11111111111111111111111111111111 invoke [1]{RESET}")
        );
    }

    #[test]
    fn process_instruction_prefix_is_preserved() {
        assert_eq!(
            format_line("process_instruction: ComputeBudget1234 [1]"),
            format!("{DARK_GRAY}process_instruction: ComputeBudget1234 [1]{RESET}")
        );
    }

    #[test]
    fn solana_runtime_prefix_is_preserved() {
        // The `solana_runtime:` prefix is recognised as the runtime prefix and
        // normalised to `solana_runtime: `, staying in Low importance.
        let formatted = format_line("solana_runtime: :program::process_instruction: hi");
        assert_eq!(
            formatted,
            format!("{DARK_GRAY}solana_runtime: :program::process_instruction: hi{RESET}")
        );
    }

    /// A bare line with no known prefix is emitted verbatim in Low importance.
    #[test]
    fn lines_without_a_known_prefix_are_emitted_verbatim() {
        assert_eq!(format_line("just some text"), format!("{DARK_GRAY}just some text{RESET}"));
        assert_eq!(format_line(""), format!("{DARK_GRAY}{RESET}"));
    }

    /// The `Program` prefix must be matched after `Program log:`, otherwise
    /// `Program log:` lines would be routed into the `Program` branch.
    #[test]
    fn program_log_prefix_is_matched_before_the_bare_program_prefix() {
        assert_eq!(format_line("Program log: x"), format!("{GREEN}x{RESET}"));
        assert_eq!(format_line("Program logx: y"), format!("{DARK_GRAY}Program logx: y{RESET}"));
    }

    #[test]
    fn format_logs_skips_empty_lines() {
        let logs = vec![
            String::from("Program log: first"),
            String::new(),
            String::from(""),
            String::from("Program log: second"),
        ];
        let formatted = format_logs(&logs);

        assert_eq!(formatted, format!("{GREEN}first{RESET}\n{GREEN}second{RESET}\n"));
    }

    #[test]
    fn format_logs_of_an_empty_slice_is_empty() {
        assert_eq!(format_logs(&[]), "");
    }

    #[test]
    fn format_logs_terminates_every_line_with_a_newline() {
        let logs = vec![String::from("a"), String::from("b"), String::new()];
        let formatted = format_logs(&logs);
        assert_eq!(formatted.lines().count(), 2);
        assert!(formatted.ends_with('\n'));
    }

    /// Multi-byte characters and quoting must survive formatting unchanged.
    #[test]
    fn arbitrary_lines_are_formatted_without_corruption() {
        let logs = vec![
            String::from("Program log: 日本語 ✓ 🎉"),
            String::from(
                "Program 11111111111111111111111111111111 consumed 0 of 200000 compute units",
            ),
            String::from("no prefix with \"quotes\" and \\backslash|"),
        ];
        let formatted = format_logs(&logs);
        assert!(formatted.contains("日本語 ✓ 🎉"));
        assert!(formatted.contains("no prefix with \"quotes\" and \\backslash|"));
    }

    // Property: each non-empty input line yields exactly one output line, and
    // every produced line is terminated by a reset sequence.
    proptest! {
        #[test]
        fn format_logs_emits_one_painted_line_per_non_empty_input(
            lines in prop::collection::vec("[^\r\n]*", 0..10),
        ) {
            let logs: Vec<String> = lines.clone();
            let formatted = format_logs(&logs);
            let expected = logs.iter().filter(|line| !line.is_empty()).count();

            prop_assert_eq!(formatted.lines().count(), expected);
            prop_assert_eq!(formatted.matches(RESET).count(), expected);
        }
    }

    // Property: `format_line` output always re-paints the line, i.e. it is
    // wrapped in exactly one style and never leaks a raw control character
    // other than the escape sequences `nu-ansi-term` emits.
    proptest! {
        #[test]
        fn format_line_always_wraps_the_rendered_text(line in ".{0,64}") {
            let formatted = format_line(&line);
            // Bound first: `prop_assert!` treats its single expression as a
            // format string, so literal braces must not appear inline.
            let escape = '\u{1b}';
            prop_assert!(formatted.ends_with(RESET));
            prop_assert!(formatted.contains(escape));
            // The style prefix is one of the four palette entries.
            prop_assert!(
                [BOLD_RED, GREEN, BOLD_GRAY, DARK_GRAY]
                    .iter()
                    .any(|style| formatted.starts_with(style))
            );
        }
    }

    // Property: a `Program log:` line never keeps its `Program log:` prefix in
    // the rendered output, whatever the body and whatever importance it gets.
    proptest! {
        #[test]
        fn program_log_lines_never_keep_their_prefix(body in ".*") {
            let formatted = format_line(&format!("Program log: {body}"));
            let rendered = formatted
                .strip_prefix(BOLD_RED)
                .or_else(|| formatted.strip_prefix(GREEN))
                .and_then(|rest| rest.strip_suffix(RESET))
                .expect("program log lines are painted with a known style");
            prop_assert!(!rendered.starts_with("Program log:"));
        }
    }
}