metrics: fix race condition in signal handler

The METRICS.write() method operates on the false assumption
that it is only being called from one thread (VMM).
This is not true since it is called from the signal handlers
as well (which may be executed on any thread).

The race condition appears due to the fact that metrics state is
mutated during serialization for SharedIncMetrics (old value gets
assigned the new value after the difference is serialized).
The METRICS.write() method only holds the lock when writing to the
file, but there is no lock held while serialising the metrics to JSON.

VMM THREAD (1/MINUTE)   VCPU THREAD (SIGNAL HANDLER)
                        new_val=1
dif=new_val-old_val(=1)
old_val=new_val (=1)
                        dif=new_val-old_val (=0)
                        write(dif) (=0)
                        exit()
Because of the exit(), the VMM thread no longer gets a chance to
write the metric.

We now use SharedStoreMetric for deadly signal metrics,
which does not have this type of race condition because it is not
mutated on serialization.

It also does not make sense to have a SharedIncMetric for deadly
signal metrics, which can only ever be 0 or 1.

This was the root-cause of the intermittent failure in
test_custom_seccomp.py::test_failing_fiter

Signed-off-by: alindima <[email protected]>

Author: alindima

src/firecracker/src/main.rs

@@ -11,7 +11,7 @@ use std::process;
 use std::sync::{Arc, Mutex};
 
 use event_manager::SubscriberOps;
-use logger::{error, info, IncMetric, ProcessTimeReporter, LOGGER, METRICS};
+use logger::{error, info, ProcessTimeReporter, StoreMetric, LOGGER, METRICS};
 use mmds::MMDS;
 use seccompiler::BpfThreadMap;
 use snapshot::Snapshot;
@@ -96,7 +96,7 @@ fn main_exitable() -> ExitCode {
             );
         }
 
-        METRICS.vmm.panic_count.inc();
+        METRICS.vmm.panic_count.store(1);
 
         // Write the metrics before aborting.
         if let Err(e) = METRICS.write() {

src/firecracker/src/metrics.rs

@@ -46,8 +46,6 @@ impl PeriodicMetrics {
     }
 
     fn write_metrics(&mut self) {
-        // Please note that, if METRICS has no output file configured yet, it will write to
-        // stdout, so metrics writing will interfere with console output.
         if let Err(e) = METRICS.write() {
             METRICS.logger.missed_metrics_count.inc();
             error!("Failed to write metrics: {}", e);

src/logger/src/metrics.rs

@@ -134,10 +134,19 @@ impl<T: Serialize> Metrics<T> {
     /// Upon success, the function will return `True` (if metrics system was initialized and metrics
     /// were successfully written to disk) or `False` (if metrics system was not yet initialized).
     ///
-    /// This function is supposed to be called only from a single thread and
+    /// This function is usually supposed to be called only from a single thread and
     /// is not meant to be used in a multithreaded scenario. The reason
     /// `metrics_buf` is enclosed in a `Mutex` is that `lazy_static` enforces
     /// thread-safety on all its members.
+    /// The only exception is for signal handlers that result in process exit, which may be run on
+    /// any thread. To prevent the race condition present in the serialisation step of
+    /// SharedIncMetrics, deadly signals use SharedStoreMetrics instead (which have a thread-safe
+    /// serialise implementation).
+    /// The only known caveat is that other metrics may not be properly written before exiting from
+    /// a signal handler. We make this compromise since the process will be killed anyway and the
+    /// important metric in this case is the signal one.
+    /// The alternative is to hold a Mutex over the entire function call, but this increases the
+    /// known deadlock potential.
     pub fn write(&self) -> Result<bool, MetricsError> {
         if self.is_initialized.load(Ordering::Relaxed) {
             match serde_json::to_string(&self.app_metrics) {
@@ -674,7 +683,7 @@ impl RtcEvents for RTCDeviceMetrics {
 #[derive(Default, Serialize)]
 pub struct SeccompMetrics {
     /// Number of errors inside the seccomp filtering.
-    pub num_faults: SharedIncMetric,
+    pub num_faults: SharedStoreMetric,
 }
 
 /// Metrics specific to the UART device.
@@ -695,22 +704,25 @@ pub struct SerialDeviceMetrics {
 }
 
 /// Metrics related to signals.
+/// Deadly signals must be of `SharedStoreMetric` type, since they can ever be either 0 or 1.
+/// This avoids a tricky race condition caused by the unatomic serialize method of
+/// `SharedIncMetric`, between two threads calling `METRICS.write()`.
 #[derive(Default, Serialize)]
 pub struct SignalMetrics {
     /// Number of times that SIGBUS was handled.
-    pub sigbus: SharedIncMetric,
+    pub sigbus: SharedStoreMetric,
     /// Number of times that SIGSEGV was handled.
-    pub sigsegv: SharedIncMetric,
+    pub sigsegv: SharedStoreMetric,
     /// Number of times that SIGXFSZ was handled.
-    pub sigxfsz: SharedIncMetric,
+    pub sigxfsz: SharedStoreMetric,
     /// Number of times that SIGXCPU was handled.
-    pub sigxcpu: SharedIncMetric,
+    pub sigxcpu: SharedStoreMetric,
     /// Number of times that SIGPIPE was handled.
     pub sigpipe: SharedIncMetric,
     /// Number of times that SIGHUP was handled.
-    pub sighup: SharedIncMetric,
+    pub sighup: SharedStoreMetric,
     /// Number of times that SIGILL was handled.
-    pub sigill: SharedIncMetric,
+    pub sigill: SharedStoreMetric,
 }
 
 /// Metrics specific to VCPUs' mode of functioning.
@@ -736,7 +748,7 @@ pub struct VmmMetrics {
     /// Number of device related events received for a VM.
     pub device_events: SharedIncMetric,
     /// Metric for signaling a panic has occurred.
-    pub panic_count: SharedIncMetric,
+    pub panic_count: SharedStoreMetric,
 }
 
 /// Vsock-related metrics.

src/vmm/src/signal_handler.rs

@@ -6,7 +6,7 @@ use libc::{
 };
 
 use crate::{ExitCode, FC_EXIT_CODE_UNEXPECTED_ERROR};
-use logger::{error, IncMetric, METRICS};
+use logger::{error, IncMetric, StoreMetric, METRICS};
 use utils::signal::register_signal_handler;
 
 // The offset of `si_syscall` (offending syscall identifier) within the siginfo structure
@@ -39,7 +39,7 @@ macro_rules! generate_handler {
             if num != si_signo || num != $signal_name {
                 exit_with_code(FC_EXIT_CODE_UNEXPECTED_ERROR);
             }
-            $signal_metric.inc();
+            $signal_metric.store(1);
 
             error!(
                 "Shutting down VM after intercepting signal {}, code {}.",
@@ -209,31 +209,31 @@ mod tests {
             let filter = make_test_seccomp_bpf_filter();
 
             assert!(seccompiler::apply_filter(&filter).is_ok());
-            assert_eq!(METRICS.seccomp.num_faults.count(), 0);
+            assert_eq!(METRICS.seccomp.num_faults.fetch(), 0);
 
             // Call the forbidden `SYS_mkdirat`.
             unsafe { libc::syscall(libc::SYS_mkdirat, "/foo/bar\0") };
 
             // Call SIGBUS signal handler.
-            assert_eq!(METRICS.signals.sigbus.count(), 0);
+            assert_eq!(METRICS.signals.sigbus.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGBUS);
             }
 
             // Call SIGSEGV signal handler.
-            assert_eq!(METRICS.signals.sigsegv.count(), 0);
+            assert_eq!(METRICS.signals.sigsegv.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGSEGV);
             }
 
             // Call SIGXFSZ signal handler.
-            assert_eq!(METRICS.signals.sigxfsz.count(), 0);
+            assert_eq!(METRICS.signals.sigxfsz.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGXFSZ);
             }
 
             // Call SIGXCPU signal handler.
-            assert_eq!(METRICS.signals.sigxcpu.count(), 0);
+            assert_eq!(METRICS.signals.sigxcpu.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGXCPU);
             }
@@ -245,13 +245,13 @@ mod tests {
             }
 
             // Call SIGHUP signal handler.
-            assert_eq!(METRICS.signals.sighup.count(), 0);
+            assert_eq!(METRICS.signals.sighup.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGHUP);
             }
 
             // Call SIGILL signal handler.
-            assert_eq!(METRICS.signals.sigill.count(), 0);
+            assert_eq!(METRICS.signals.sigill.fetch(), 0);
             unsafe {
                 syscall(libc::SYS_kill, process::id(), SIGILL);
             }
@@ -268,17 +268,17 @@ mod tests {
         // tests, so we use this as an heuristic to decide if we check the assertion.
         if cpu_count() > 1 {
             // The signal handler should let the program continue during unit tests.
-            assert!(METRICS.seccomp.num_faults.count() >= 1);
+            assert!(METRICS.seccomp.num_faults.fetch() >= 1);
         }
-        assert!(METRICS.signals.sigbus.count() >= 1);
-        assert!(METRICS.signals.sigsegv.count() >= 1);
-        assert!(METRICS.signals.sigxfsz.count() >= 1);
-        assert!(METRICS.signals.sigxcpu.count() >= 1);
+        assert!(METRICS.signals.sigbus.fetch() >= 1);
+        assert!(METRICS.signals.sigsegv.fetch() >= 1);
+        assert!(METRICS.signals.sigxfsz.fetch() >= 1);
+        assert!(METRICS.signals.sigxcpu.fetch() >= 1);
         assert!(METRICS.signals.sigpipe.count() >= 1);
-        assert!(METRICS.signals.sighup.count() >= 1);
+        assert!(METRICS.signals.sighup.fetch() >= 1);
         // Workaround to GitHub issue 2216.
         #[cfg(not(target_arch = "aarch64"))]
-        assert!(METRICS.signals.sigill.count() >= 1);
+        assert!(METRICS.signals.sigill.fetch() >= 1);
     }
 
     fn make_test_seccomp_bpf_filter() -> Vec<sock_filter> {

tests/integration_tests/build/test_coverage.py

@@ -31,7 +31,7 @@
 if utils.is_io_uring_supported():
     COVERAGE_DICT = {"Intel": 85.09, "AMD": 84.51, "ARM": 84.21}
 else:
-    COVERAGE_DICT = {"Intel": 82.03, "AMD": 81.5, "ARM": 81.10}
+    COVERAGE_DICT = {"Intel": 82.03, "AMD": 81.5, "ARM": 81.16}
 
 PROC_MODEL = proc.proc_type()
 

tests/integration_tests/security/test_custom_seccomp.py

@@ -205,7 +205,7 @@ def test_failing_filter(test_microvm_with_api):
     for line in lines:
         num_faults += json.loads(line)["seccomp"]["num_faults"]
 
-    assert num_faults == 1
+    assert num_faults >= 1
 
     # assert that the process was killed
     assert not psutil.pid_exists(test_microvm.jailer_clone_pid)