1use crate::api::BackendAccess;
2use crate::api::ExecuteArgs;
3use crate::api::Module;
4use crate::interpreter::{InterpretedInstance, InterpreterContext};
5use crate::source_cache::SourceCache;
6use core::mem::MaybeUninit;
7use polkavm_common::error::Trap;
8use polkavm_common::program::{FrameKind, Opcode, Reg};
9use polkavm_common::utils::Access;
10
11pub(crate) struct Tracer {
12 module: Module,
13 source_cache: SourceCache,
14 program_counter_history: [u32; 8],
15 program_counter_history_position: usize,
16 crosscheck_interpreter: Option<InterpretedInstance>,
17 crosscheck_reg: Option<(Reg, u32)>,
18 crosscheck_store: Option<(u32, u32)>,
19 crosscheck_store_bytes: [u8; 8],
20 crosscheck_execution_flags: u32,
21 current_line_program_position: Option<(usize, usize)>,
22 current_source_location: Option<(u32, u32)>,
23
24 enable_store_crosschecks: bool,
25}
26
27impl Tracer {
28 pub fn new(module: &Module) -> Self {
29 Tracer {
30 program_counter_history: [!0; 8],
31 program_counter_history_position: 0,
32 crosscheck_interpreter: if module.compiled_module().is_some() {
33 InterpretedInstance::new_from_module(module).ok()
34 } else {
35 None
36 },
37 module: module.clone(),
38 source_cache: SourceCache::default(),
39 crosscheck_reg: None,
40 crosscheck_store: None,
41 crosscheck_store_bytes: Default::default(),
42 crosscheck_execution_flags: 0,
43 current_line_program_position: None,
44 current_source_location: None,
45
46 enable_store_crosschecks: false,
48 }
49 }
50
51 pub fn on_before_execute(&mut self, args: &ExecuteArgs) {
52 if let Some(ref mut interpreter) = self.crosscheck_interpreter {
53 self.crosscheck_execution_flags = args.flags;
54 interpreter.prepare_for_execution(args);
55 }
56 }
57
58 pub fn on_after_execute(&mut self) {
59 if let Some(ref mut interpreter) = self.crosscheck_interpreter {
60 interpreter.finish_execution(self.crosscheck_execution_flags);
61 }
62 }
63
64 pub fn on_trace(&mut self, access: &mut BackendAccess) -> Result<(), Trap> {
65 assert!(self.module.is_debug_trace_execution_enabled());
66
67 self.crosscheck_last_instruction(access)?;
68
69 let program_counter = access
70 .program_counter()
71 .expect("internal error: tracer called without valid program counter");
72
73 self.trace_current_instruction_source(program_counter);
74
75 let instruction = self.module.instructions()[program_counter as usize];
76 if let Some(native_address) = access.native_program_counter() {
77 log::trace!("0x{native_address:x}: #{program_counter}: {instruction}");
78 } else {
79 log::trace!("#{program_counter}: {instruction}");
80 }
81
82 self.step_crosscheck_interpreter(program_counter)?;
83 Ok(())
84 }
85
86 pub fn on_set_reg_in_hostcall(&mut self, reg: Reg, value: u32) {
87 if let Some(ref mut interpreter) = self.crosscheck_interpreter {
88 interpreter.access().set_reg(reg, value);
89 }
90 }
91
92 pub fn on_memory_write_in_hostcall(&mut self, address: u32, data: &[u8], success: bool) -> Result<(), Trap> {
93 if let Some(ref mut interpreter) = self.crosscheck_interpreter {
94 let expected_result = interpreter.access().write_memory(address, data);
95 let expected_success = expected_result.is_ok();
96 if success != expected_result.is_ok() {
97 let address_end = u64::from(address) + data.len() as u64;
98 log::error!("Memory write in hostcall mismatch when writing to 0x{address:x}..0x{address_end:x}! (crosscheck interpreter = {expected_success}, actual = {success})");
99 }
100 }
101
102 Ok(())
103 }
104
105 fn debug_print_history(&self) {
106 log::error!("Program counter history:");
107 for nth in (0..self.program_counter_history.len()).rev() {
108 let pc = self.program_counter_history[(self.program_counter_history_position + nth) % self.program_counter_history.len()];
109 if pc == !0 {
110 continue;
111 }
112
113 self.module.debug_print_location(log::Level::Error, pc);
114 }
115 }
116
117 fn crosscheck_last_instruction(&mut self, access: &mut BackendAccess) -> Result<(), Trap> {
118 if let Some((reg, expected_value)) = self.crosscheck_reg.take() {
119 let value = access.get_reg(reg);
120 if value != expected_value {
121 log::error!("Register value mismatch! Crosscheck interpreter has {reg} = 0x{expected_value:x}, actual execution has {reg} = 0x{value:x}");
122 self.debug_print_history();
123 return Err(Trap::default());
124 }
125 }
126
127 if let Some((address, length)) = self.crosscheck_store.take() {
128 let bytes_expected = &self.crosscheck_store_bytes[..length as usize];
129 let mut bytes_actual: [MaybeUninit<u8>; 8] = [MaybeUninit::uninit(); 8];
130 let bytes_actual = match access.read_memory_into_slice(address, &mut bytes_actual[..length as usize]) {
131 Ok(bytes_actual) => bytes_actual,
132 Err(error) => {
133 log::error!(
134 "Store value mismatch! Couldn't fetch memory at [0x{address:x}..+{length}] from the actual execution: {error}"
135 );
136 return Err(Trap::default());
137 }
138 };
139 if bytes_actual != bytes_expected {
140 log::error!("Store value mismatch! Crosscheck interpreter has [0x{address:x}..+{length}] = {bytes_expected:?}, actual execution has [0x{address:x}..+{length}] = {bytes_actual:?}");
141 return Err(Trap::default());
142 }
143 }
144
145 Ok(())
146 }
147
148 fn trace_current_instruction_source(&mut self, program_counter: u32) {
149 #[cfg(not(windows))]
150 const VT_DARK: &str = "\x1B[1;30m";
151 #[cfg(not(windows))]
152 const VT_GREEN: &str = "\x1B[1;32m";
153 #[cfg(not(windows))]
154 const VT_RESET: &str = "\x1B[0m";
155
156 #[cfg(windows)]
157 const VT_DARK: &str = "";
158 #[cfg(windows)]
159 const VT_GREEN: &str = "";
160 #[cfg(windows)]
161 const VT_RESET: &str = "";
162
163 if !log::log_enabled!(log::Level::Trace) {
164 return;
165 }
166
167 let blob = self.module.blob();
168 let mut line_program = match blob.get_debug_line_program_at(program_counter) {
169 Err(error) => {
170 log::warn!("Failed to get line program for instruction #{program_counter}: {error}");
171 self.current_source_location = None;
172 return;
173 }
174 Ok(None) => {
175 log::trace!(" (f) (none)");
176 self.current_source_location = None;
177 return;
178 }
179 Ok(Some(line_program)) => line_program,
180 };
181
182 let line_program_index = line_program.entry_index();
183
184 let location_ref = loop {
186 let region_info = match line_program.run() {
187 Ok(Some(region_info)) => region_info,
188 Ok(None) => {
189 debug_assert!(false, "region should have been found in line program but wasn't");
190 break None;
191 }
192 Err(error) => {
193 log::warn!("Failed to run line program for instruction #{program_counter}: {error}");
194 self.current_source_location = None;
195 return;
196 }
197 };
198
199 if !region_info.instruction_range().contains(&program_counter) {
200 continue;
201 }
202
203 let new_line_program_position = (line_program_index, region_info.entry_index());
204 if self.current_line_program_position == Some(new_line_program_position) {
205 log::trace!(" {VT_DARK}(location unchanged){VT_RESET}");
206 return;
207 }
208
209 self.current_line_program_position = Some(new_line_program_position);
210
211 let mut location_ref = None;
212 for frame in region_info.frames() {
213 let full_name = match frame.full_name() {
214 Ok(full_name) => full_name,
215 Err(error) => {
216 log::warn!("Failed to fetch a frame full name at #{program_counter}: {error}");
217 self.current_source_location = None;
218 return;
219 }
220 };
221
222 let location = match frame.location() {
223 Ok(location) => location,
224 Err(error) => {
225 log::warn!("Failed to fetch a frame location at #{program_counter}: {error}");
226 self.current_source_location = None;
227 return;
228 }
229 };
230
231 let kind = match frame.kind() {
232 FrameKind::Enter => 'f',
233 FrameKind::Call => 'c',
234 FrameKind::Line => 'l',
235 };
236
237 if let Some(location) = location {
238 log::trace!(" ({kind}) '{full_name}' {VT_DARK}[{location}]{VT_RESET}");
239 } else {
240 log::trace!(" ({kind}) '{full_name}'");
241 }
242
243 location_ref = if let (Some(offset), Some(line)) = (frame.path_debug_string_offset(), frame.line()) {
244 Some((offset, line))
245 } else {
246 None
247 };
248 }
249
250 break location_ref;
251 };
252
253 if self.current_source_location == location_ref {
254 return;
255 }
256
257 self.current_source_location = location_ref;
258 let Some((path_offset, line)) = location_ref else {
259 return;
260 };
261
262 let Ok(path) = blob.get_debug_string(path_offset) else {
263 return;
264 };
265
266 if let Some(source_line) = self.source_cache.lookup_source_line(path, line) {
267 log::trace!(" | {VT_GREEN}{source_line}{VT_RESET}");
268 }
269 }
270
271 fn step_crosscheck_interpreter(&mut self, program_counter: u32) -> Result<(), Trap> {
272 let Some(ref mut interpreter) = self.crosscheck_interpreter else {
273 return Ok(());
274 };
275
276 let expected_program_counter = interpreter.access().program_counter().unwrap();
277 if expected_program_counter != program_counter {
278 log::error!("Program counter mismatch! Crosscheck interpreter returned #{expected_program_counter}, actual execution returned #{program_counter}");
279 self.module.debug_print_location(log::Level::Error, expected_program_counter);
280 self.module.debug_print_location(log::Level::Error, program_counter);
281 self.debug_print_history();
282 return Err(Trap::default());
283 }
284
285 self.program_counter_history[self.program_counter_history_position] = program_counter;
286 self.program_counter_history_position = (self.program_counter_history_position + 1) % self.program_counter_history.len();
287
288 let instruction = self.module.instructions()[program_counter as usize];
289 if matches!(instruction.opcode(), Opcode::trap) {
290 return Ok(());
291 }
292
293 let mut on_hostcall = |_hostcall: u32, _access: BackendAccess<'_>| -> Result<(), Trap> { Ok(()) };
294 let mut on_set_reg = |reg: Reg, value: u32| -> Result<(), Trap> {
295 assert!(self.crosscheck_reg.is_none());
296 self.crosscheck_reg = Some((reg, value));
297 Ok(())
298 };
299
300 let mut on_store = |address: u32, data: &[u8]| -> Result<(), Trap> {
301 if self.enable_store_crosschecks {
302 assert!(self.crosscheck_store.is_none());
303 assert!(data.len() <= 8);
304 self.crosscheck_store = Some((address, data.len() as u32));
305 self.crosscheck_store_bytes[..data.len()].copy_from_slice(data);
306 }
307 Ok(())
308 };
309
310 let mut ctx = InterpreterContext::default();
311 ctx.set_on_hostcall(&mut on_hostcall);
312 ctx.set_on_set_reg(&mut on_set_reg);
313 ctx.set_on_store(&mut on_store);
314
315 if let Err(error) = interpreter.step_once(ctx) {
316 log::error!("Crosscheck interpreter encountered error: {}", error);
317 self.debug_print_history();
318 return Err(Trap::default());
319 }
320
321 Ok(())
322 }
323}