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

use crate::{
    common::{
        guards_guard, ACTIVE_GUARD_MIN_ELAPSED, ACTIVE_GUARD_NO_ACTIVITY_INTERVAL,
        GUARD_WATCHER_POLL_INTERVAL, IMMORTAL_TIMEOUT,
    },
    error::LockType,
};
use backtrace::Backtrace;
use snowflake::ProcessUniqueId;
use std::{
    thread,
    time::{Duration, Instant},
};

pub(crate) struct GuardTracker {
    pub(crate) puid: ProcessUniqueId,
    pub(crate) created: Instant,
    pub(crate) backtrace: Backtrace,
    pub(crate) lock_type: LockType,
    pub(crate) immortal: bool,
    pub(crate) annotation: Option<String>,
}

impl GuardTracker {
    pub fn new(puid: ProcessUniqueId, lock_type: LockType) -> Self {
        Self {
            puid,
            lock_type,
            created: Instant::now(),
            backtrace: Backtrace::new_unresolved(),
            immortal: false,
            annotation: None,
        }
    }

    pub fn report_and_update(&mut self) -> Option<(i64, String)> {
        let elapsed = Instant::now().duration_since(self.created);
        if elapsed > *ACTIVE_GUARD_MIN_ELAPSED {
            let elapsed_ms = elapsed.as_millis() as i64;
            if !self.immortal && elapsed > *IMMORTAL_TIMEOUT {
                self.immortalize();
            }
            let lock_type_str = format!("{:?}", self.lock_type);
            let report = if self.immortal {
                format!(
                    "{:<6} {:<13} {:>12} [!!!]",
                    lock_type_str, self.puid, elapsed_ms
                )
            } else {
                format!("{:<6} {:<13} {:>12}", lock_type_str, self.puid, elapsed_ms)
            };
            Some((elapsed_ms, report))
        } else {
            None
        }
    }

    pub fn report_header() -> String {
        format!("{:6} {:^13} {:>12}", "KIND", "PUID", "ELAPSED (ms)")
    }

    fn immortalize(&mut self) {
        if self.immortal {
            return;
        }
        self.immortal = true;
        self.backtrace.resolve();
        let annotation = self
            .annotation
            .as_ref()
            .map(|a| format!("\nAnnotation: {}\n", a))
            .unwrap_or_default();
        error!(
            r"

        !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
        !!! IMMORTAL LOCK GUARD FOUND !!!
        !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

{type:?} guard {puid} lived for > {time} seconds.{annotation}
Backtrace at the moment of guard creation follows:

{backtrace:?}",
            type=self.lock_type,
            puid=self.puid,
            time=IMMORTAL_TIMEOUT.as_secs(),
            annotation=annotation,
            backtrace=self.backtrace
        );
    }
}

pub fn spawn_locksmith_guard_watcher() {
    debug!("spawning locksmith_guard_watcher");
    let _ = thread::Builder::new()
        .name(format!(
            "locksmith_guard_watcher/{}",
            ProcessUniqueId::new().to_string()
        ))
        .spawn(move || {
            let mut inactive_for = Duration::from_millis(0);
            loop {
                let mut reports: Vec<(i64, String)> = {
                    guards_guard()
                        .values_mut()
                        .filter_map(|gt| gt.report_and_update())
                        .collect()
                };
                if reports.len() > 0 {
                    inactive_for = Duration::from_millis(0);
                    reports.sort_unstable_by_key(|(elapsed, _)| -*elapsed);
                    let num_active = reports.len();
                    let lines: Vec<String> =
                        reports.into_iter().map(|(_, report)| report).collect();
                    let output = lines.join("\n");
                    debug!(
                        "tracking {} active guard(s) alive for > {}ms:\n{}\n{}",
                        num_active,
                        ACTIVE_GUARD_MIN_ELAPSED.as_millis(),
                        GuardTracker::report_header(),
                        output
                    );
                } else {
                    inactive_for += *GUARD_WATCHER_POLL_INTERVAL;
                    if inactive_for > *ACTIVE_GUARD_NO_ACTIVITY_INTERVAL {
                        debug!(
                            "no active guards alive > {:?}ms for the last {:?} seconds",
                            ACTIVE_GUARD_MIN_ELAPSED.as_millis(),
                            ACTIVE_GUARD_NO_ACTIVITY_INTERVAL.as_secs(),
                        );
                        inactive_for = Duration::from_millis(0);
                    }
                }

                thread::sleep(*GUARD_WATCHER_POLL_INTERVAL);
            }
        });
}