tsffs/log/
mod.rs

1// Copyright (C) 2024 Intel Corporation
2// SPDX-License-Identifier: Apache-2.0
3
4//! Logging
5
6use crate::{fuzzer::messages::FuzzerMessage, Tsffs};
7use anyhow::{anyhow, Result};
8use chrono::Utc;
9use serde::Serialize;
10use simics::{info, AsConfObject};
11use std::{fs::OpenOptions, io::Write, time::SystemTime};
12
13#[derive(Clone, Debug, Serialize)]
14pub(crate) struct LogMessageEdge {
15    pub pc: u64,
16    pub afl_idx: u64,
17}
18
19#[derive(Clone, Debug, Serialize)]
20pub(crate) struct LogMessageInteresting {
21    pub indices: Vec<usize>,
22    pub input: Vec<u8>,
23    pub edges: Vec<LogMessageEdge>,
24}
25
26pub(crate) type LogMessageSolution = LogMessageInteresting;
27pub(crate) type LogMessageTimeout = LogMessageInteresting;
28
29#[derive(Clone, Debug, Serialize)]
30pub(crate) enum LogMessage {
31    Startup {
32        timestamp: String,
33    },
34    Message {
35        timestamp: String,
36        message: String,
37    },
38    Interesting {
39        timestamp: String,
40        message: LogMessageInteresting,
41    },
42    Solution {
43        timestamp: String,
44        message: LogMessageSolution,
45    },
46    Timeout {
47        timestamp: String,
48        message: LogMessageTimeout,
49    },
50    Heartbeat {
51        iterations: usize,
52        solutions: usize,
53        timeouts: usize,
54        edges: usize,
55        timestamp: String,
56    },
57}
58
59impl LogMessage {
60    pub(crate) fn startup() -> Self {
61        Self::Startup {
62            timestamp: Utc::now().to_rfc3339(),
63        }
64    }
65
66    pub(crate) fn message(message: String) -> Self {
67        Self::Message {
68            timestamp: Utc::now().to_rfc3339(),
69            message,
70        }
71    }
72
73    pub(crate) fn interesting(
74        indices: Vec<usize>,
75        input: Vec<u8>,
76        edges: Vec<LogMessageEdge>,
77    ) -> Self {
78        Self::Interesting {
79            timestamp: Utc::now().to_rfc3339(),
80            message: LogMessageInteresting {
81                indices,
82                input,
83                edges,
84            },
85        }
86    }
87
88    pub(crate) fn heartbeat(
89        iterations: usize,
90        solutions: usize,
91        timeouts: usize,
92        edges: usize,
93    ) -> Self {
94        Self::Heartbeat {
95            iterations,
96            solutions,
97            timeouts,
98            edges,
99            timestamp: Utc::now().to_rfc3339(),
100        }
101    }
102}
103
104impl Tsffs {
105    pub fn log_messages(&mut self) -> Result<()> {
106        let messages = self
107            .fuzzer_messages
108            .get()
109            .map(|m| m.try_iter().collect::<Vec<_>>())
110            .unwrap_or_default();
111
112        messages.iter().try_for_each(|m| {
113            match m {
114                FuzzerMessage::String(s) => {
115                    info!(self.as_conf_object(), "Fuzzer message: {s}");
116                    self.log(LogMessage::message(s.clone()))?;
117                }
118                FuzzerMessage::Interesting { indices, input } => {
119                    info!(
120                        self.as_conf_object(),
121                        "Interesting input for AFL indices {indices:?} with input {input:?}"
122                    );
123
124                    if !self.edges_seen_since_last.is_empty() {
125                        let mut edges = self
126                            .edges_seen_since_last
127                            .iter()
128                            .map(|(p, a)| LogMessageEdge {
129                                pc: *p,
130                                afl_idx: *a,
131                            })
132                            .collect::<Vec<_>>();
133
134                        edges.sort_by(|e1, e2| e1.pc.cmp(&e2.pc));
135
136                        info!(
137                            self.as_conf_object(),
138                            "{} Interesting edges seen since last report ({} edges total)",
139                            self.edges_seen_since_last.len(),
140                            self.edges_seen.len(),
141                        );
142
143                        self.log(LogMessage::interesting(
144                            indices.clone(),
145                            input.clone(),
146                            edges,
147                        ))?;
148
149                        self.edges_seen_since_last.clear();
150                    }
151
152                    if self.save_interesting_execution_traces {
153                        self.save_execution_trace()?;
154                    }
155
156                    if self.symbolic_coverage {
157                        self.save_symbolic_coverage()?;
158                    }
159                }
160                FuzzerMessage::Crash { indices, input } => {
161                    info!(
162                        self.as_conf_object(),
163                        "Solution input for AFL indices {indices:?} with input {input:?}"
164                    );
165
166                    if !self.edges_seen_since_last.is_empty() {
167                        let mut edges = self
168                            .edges_seen_since_last
169                            .iter()
170                            .map(|(p, a)| LogMessageEdge {
171                                pc: *p,
172                                afl_idx: *a,
173                            })
174                            .collect::<Vec<_>>();
175
176                        edges.sort_by(|e1, e2| e1.pc.cmp(&e2.pc));
177
178                        self.log(LogMessage::Solution {
179                            timestamp: Utc::now().to_rfc3339(),
180                            message: LogMessageSolution {
181                                indices: indices.clone(),
182                                input: input.clone(),
183                                edges,
184                            },
185                        })?;
186                    }
187
188                    if self.save_solution_execution_traces {
189                        self.save_execution_trace()?;
190                    }
191
192                    if self.symbolic_coverage {
193                        self.save_symbolic_coverage()?;
194                    }
195                }
196                FuzzerMessage::Timeout { indices, input } => {
197                    info!(
198                        self.as_conf_object(),
199                        "Timeout input for AFL indices {indices:?} with input {input:?}"
200                    );
201
202                    if !self.edges_seen_since_last.is_empty() {
203                        let mut edges = self
204                            .edges_seen_since_last
205                            .iter()
206                            .map(|(p, a)| LogMessageEdge {
207                                pc: *p,
208                                afl_idx: *a,
209                            })
210                            .collect::<Vec<_>>();
211
212                        edges.sort_by(|e1, e2| e1.pc.cmp(&e2.pc));
213
214                        self.log(LogMessage::Timeout {
215                            timestamp: Utc::now().to_rfc3339(),
216                            message: LogMessageTimeout {
217                                indices: indices.clone(),
218                                input: input.clone(),
219                                edges,
220                            },
221                        })?;
222                    }
223
224                    if self.save_timeout_execution_traces {
225                        self.save_execution_trace()?;
226                    }
227
228                    if self.symbolic_coverage {
229                        self.save_symbolic_coverage()?;
230                    }
231                }
232            }
233
234            Ok::<(), anyhow::Error>(())
235        })?;
236
237        if self.heartbeat {
238            let last = self.last_heartbeat_time.get_or_insert_with(SystemTime::now);
239
240            if last.elapsed()?.as_secs() >= self.heartbeat_interval {
241                self.log(LogMessage::heartbeat(
242                    self.iterations,
243                    self.solutions,
244                    self.timeouts,
245                    self.edges_seen.len(),
246                ))?;
247
248                // Set the last heartbeat time
249                self.last_heartbeat_time = Some(SystemTime::now());
250            }
251        }
252
253        Ok(())
254    }
255
256    pub fn log<I>(&mut self, item: I) -> Result<()>
257    where
258        I: Serialize,
259    {
260        if !self.log_to_file {
261            return Ok(());
262        }
263
264        let item = serde_json::to_string(&item).expect("Failed to serialize item") + "\n";
265
266        let log = if let Some(log) = self.log.get_mut() {
267            log
268        } else {
269            self.log
270                .set(
271                    OpenOptions::new()
272                        .create(true)
273                        .append(true)
274                        .open(&self.log_path)?,
275                )
276                .map_err(|_| anyhow!("Log already set"))?;
277            self.log.get_mut().ok_or_else(|| anyhow!("Log not set"))?
278        };
279
280        log.write_all(item.as_bytes())?;
281
282        Ok(())
283    }
284}