f use file name/lineno, not instruction pointer, solving inlining issues

Author: TheBlueMatt

lightning/src/debug_sync.rs

@@ -5,9 +5,7 @@ use core::time::Duration;
 use std::collections::HashSet;
 use std::cell::RefCell;
 
-#[cfg(not(feature = "backtrace"))]
 use std::sync::atomic::{AtomicUsize, Ordering};
-
 use std::sync::Mutex as StdMutex;
 use std::sync::MutexGuard as StdMutexGuard;
 use std::sync::RwLock as StdRwLock;
@@ -52,11 +50,10 @@ thread_local! {
 	/// We track the set of locks currently held by a reference to their `LockMetadata`
 	static LOCKS_HELD: RefCell<HashSet<Arc<LockMetadata>>> = RefCell::new(HashSet::new());
 }
-#[cfg(not(feature = "backtrace"))]
 static LOCK_IDX: AtomicUsize = AtomicUsize::new(0);
 
 #[cfg(feature = "backtrace")]
-static mut LOCKS: Option<StdMutex<HashMap<u64, Arc<LockMetadata>>>> = None;
+static mut LOCKS: Option<StdMutex<HashMap<String, Arc<LockMetadata>>>> = None;
 #[cfg(feature = "backtrace")]
 static LOCKS_INIT: Once = Once::new();
 
@@ -94,40 +91,36 @@ impl std::hash::Hash for LockDep {
 	fn hash<H: std::hash::Hasher>(&self, hasher: &mut H) { hasher.write_u64(self.lock.lock_idx); }
 }
 
+#[cfg(feature = "backtrace")]
+fn get_construction_location(backtrace: &Backtrace) -> String {
+	// Find the first frame which is after `debug_sync` (or which is in our tests) and use
+	// that as the mutex construction site. Note that the first few frames may be in
+	// `backtrace`, so we have to ignore those.
+	let sync_mutex_constr_regex = regex::Regex::new(r"lightning.*debug_sync.*new").unwrap();
+	let mut found_debug_sync = false;
+	for frame in backtrace.frames() {
+		for symbol in frame.symbols() {
+			let symbol_name = symbol.name().unwrap().as_str().unwrap();
+			if !sync_mutex_constr_regex.is_match(symbol_name) {
+				if found_debug_sync {
+					if let Some(col) = symbol.colno() {
+						return format!("{}:{}:{}", symbol.filename().unwrap().display(), symbol.lineno().unwrap(), col);
+					} else {
+						// Windows debug symbols don't support column numbers, so fall back to
+						// line numbers only if no `colno` is available
+						return format!("{}:{}", symbol.filename().unwrap().display(), symbol.lineno().unwrap());
+					}
+				}
+			} else { found_debug_sync = true; }
+		}
+	}
+	panic!("Couldn't find mutex construction callsite");
+}
+
 impl LockMetadata {
 	fn new() -> Arc<LockMetadata> {
-		let lock_idx;
 		let backtrace = Backtrace::new();
-
-		#[cfg(not(feature = "backtrace"))]
-		{ lock_idx = LOCK_IDX.fetch_add(1, Ordering::Relaxed) as u64; }
-
-		#[cfg(feature = "backtrace")]
-		{
-			let mut ip = None;
-			// Find the first frame which is after `debug_sync` (or which is in our tests) and use
-			// that as the mutex construction site. Note that the first few frames may be in
-			// `backtrace`, so we have to ignore those.
-			let sync_mutex_constr_regex = regex::Regex::new(r"lightning.*debug_sync.*new").unwrap();
-			let mut found_debug_sync = false;
-			for frame in backtrace.frames() {
-				// If a constructor was inlined we should take the frame in which it was inlined
-				// (as its specific to the callsite), thus we look at the last available symbol,
-				// which the `backtrace` docs say will be the caller.
-				let symbol_name = frame.symbols().last().unwrap().name().unwrap().as_str().unwrap();
-				if !sync_mutex_constr_regex.is_match(symbol_name) {
-					if found_debug_sync {
-						ip = Some(frame.ip() as usize as u64);
-						break;
-					}
-				} else { found_debug_sync = true; }
-			}
-			lock_idx = ip.unwrap();
-			LOCKS_INIT.call_once(|| { unsafe { LOCKS = Some(StdMutex::new(HashMap::new())); } });
-			if let Some(metadata) = unsafe { LOCKS.as_ref() }.unwrap().lock().unwrap().get(&lock_idx) {
-				return Arc::clone(&metadata);
-			}
-		}
+		let lock_idx = LOCK_IDX.fetch_add(1, Ordering::Relaxed) as u64;
 
 		let res = Arc::new(LockMetadata {
 			locked_before: StdMutex::new(HashSet::new()),
@@ -137,8 +130,10 @@ impl LockMetadata {
 
 		#[cfg(feature = "backtrace")]
 		{
+			let lock_constr_location = get_construction_location(&res._lock_construction_bt);
+			LOCKS_INIT.call_once(|| { unsafe { LOCKS = Some(StdMutex::new(HashMap::new())); } });
 			let mut locks = unsafe { LOCKS.as_ref() }.unwrap().lock().unwrap();
-			match locks.entry(lock_idx) {
+			match locks.entry(lock_constr_location) {
 				hash_map::Entry::Occupied(e) => return Arc::clone(e.get()),
 				hash_map::Entry::Vacant(e) => { e.insert(Arc::clone(&res)); },
 			}
@@ -168,7 +163,10 @@ impl LockMetadata {
 				for locked_dep in locked.locked_before.lock().unwrap().iter() {
 					if locked_dep.lock == *this && locked_dep.lock != *locked {
 						#[cfg(feature = "backtrace")]
-						panic!("Tried to violate existing lockorder.\nMutex that should be locked after the current lock was created at the following backtrace.\nNote that to get a backtrace for the lockorder violation, you should set RUST_BACKTRACE=1\nLock constructed at:\n{:?}\n\nLock dep created at:\n{:?}\n\n", locked._lock_construction_bt, locked_dep.lockdep_trace);
+						panic!("Tried to violate existing lockorder.\nMutex that should be locked after the current lock was created at the following backtrace.\nNote that to get a backtrace for the lockorder violation, you should set RUST_BACKTRACE=1\nLock being taken constructed at: {} ({}):\n{:?}\nLock constructed at: {} ({})\n{:?}\n\nLock dep created at:\n{:?}\n\n",
+							get_construction_location(&this._lock_construction_bt), this.lock_idx, this._lock_construction_bt,
+							get_construction_location(&locked._lock_construction_bt), locked.lock_idx, locked._lock_construction_bt,
+							locked_dep.lockdep_trace);
 						#[cfg(not(feature = "backtrace"))]
 						panic!("Tried to violate existing lockorder. Build with the backtrace feature for more info.");
 					}