Use log crate for debugging output in c2rust-analyze

Replace all eprintln! macros with uses of the
log crate for more efficient and fine-grained
debugging output.

Author: ahomescu

c2rust-analyze/src/analyze.rs

@@ -25,9 +25,9 @@ use crate::type_desc::Ownership;
 use crate::util;
 use crate::util::Callee;
 use crate::util::TestAttr;
-use ::log::warn;
 use c2rust_pdg::graph::Graphs;
 use c2rust_pdg::info::NodeInfo;
+use log::{debug, info, warn};
 use rustc_hir::def::DefKind;
 use rustc_hir::def_id::CrateNum;
 use rustc_hir::def_id::DefId;
@@ -244,15 +244,15 @@ fn update_pointer_info<'tcx>(acx: &mut AnalysisCtxt<'_, 'tcx>, mir: &Body<'tcx>)
                 _ => continue,
             };
 
-            eprintln!(
+            debug!(
                 "update_pointer_info: visit assignment: {:?}[{}]: {:?}",
                 bb, i, stmt
             );
 
             if !pl.is_indirect() {
                 // This is a write directly to `pl.local`.
                 *write_count.entry(pl.local).or_insert(0) += 1;
-                eprintln!("  record write to LHS {:?}", pl);
+                debug!("  record write to LHS {:?}", pl);
             }
 
             let ref_pl = match *rv {
@@ -264,7 +264,7 @@ fn update_pointer_info<'tcx>(acx: &mut AnalysisCtxt<'_, 'tcx>, mir: &Body<'tcx>)
                 // For simplicity, we consider taking the address of a local to be a write.  We
                 // expect this not to happen for the sorts of temporary refs we're looking for.
                 if !ref_pl.is_indirect() {
-                    eprintln!("  record write to ref target {:?}", ref_pl);
+                    debug!("  record write to ref target {:?}", ref_pl);
                     *write_count.entry(ref_pl.local).or_insert(0) += 1;
                 }
 
@@ -385,7 +385,7 @@ fn mark_foreign_fixed<'tcx>(
             let fields = adt_def.all_fields();
             for field in fields {
                 let field_lty = gacx.field_ltys[&field.did];
-                eprintln!(
+                debug!(
                     "adding FIXED permission for {adt_did:?} field {:?}",
                     field.did
                 );
@@ -573,9 +573,9 @@ struct FuncInfo<'tcx> {
 }
 
 fn run(tcx: TyCtxt) {
-    eprintln!("all defs:");
+    debug!("all defs:");
     for ldid in tcx.hir_crate_items(()).definitions() {
-        eprintln!("{:?}", ldid);
+        debug!("{:?}", ldid);
     }
 
     // Load the list of fixed defs early, so any errors are reported immediately.
@@ -591,9 +591,9 @@ fn run(tcx: TyCtxt) {
     // Follow a postorder traversal, so that callers are visited after their callees.  This means
     // callee signatures will usually be up to date when we visit the call site.
     let all_fn_ldids = fn_body_owners_postorder(tcx);
-    eprintln!("callgraph traversal order:");
+    debug!("callgraph traversal order:");
     for &ldid in &all_fn_ldids {
-        eprintln!("  {:?}", ldid);
+        debug!("  {:?}", ldid);
     }
 
     populate_field_users(&mut gacx, &all_fn_ldids);
@@ -629,9 +629,9 @@ fn run(tcx: TyCtxt) {
 
     // Collect all `static` items.
     let all_static_dids = all_static_items(tcx);
-    eprintln!("statics:");
+    debug!("statics:");
     for &did in &all_static_dids {
-        eprintln!("  {:?}", did);
+        debug!("  {:?}", did);
     }
 
     // Assign global `PointerId`s for types of `static` items.
@@ -834,7 +834,7 @@ fn run(tcx: TyCtxt) {
     // Remap pointers based on equivalence classes, so all members of an equivalence class now use
     // the same `PointerId`.
     let (global_counter, global_equiv_map) = global_equiv.renumber();
-    eprintln!("global_equiv_map = {global_equiv_map:?}");
+    debug!("global_equiv_map = {global_equiv_map:?}");
     pointee_type::remap_pointers_global(
         &mut global_pointee_types,
         &global_equiv_map,
@@ -849,7 +849,7 @@ fn run(tcx: TyCtxt) {
 
         let info = func_info.get_mut(&ldid).unwrap();
         let (local_counter, local_equiv_map) = info.local_equiv.renumber(&global_equiv_map);
-        eprintln!("local_equiv_map = {local_equiv_map:?}");
+        debug!("local_equiv_map = {local_equiv_map:?}");
         pointee_type::remap_pointers_local(
             &mut global_pointee_types,
             &mut info.local_pointee_types,
@@ -1043,8 +1043,8 @@ fn run(tcx: TyCtxt) {
         &mut g_updates_forbidden,
     );
 
-    eprintln!("=== ADT Metadata ===");
-    eprintln!("{:?}", gacx.adt_metadata);
+    debug!("=== ADT Metadata ===");
+    debug!("{:?}", gacx.adt_metadata);
 
     let mut loop_count = 0;
     loop {
@@ -1110,14 +1110,14 @@ fn run(tcx: TyCtxt) {
                 let added = new & !old;
                 let removed = old & !new;
                 let kept = old & new;
-                eprintln!(
+                debug!(
                     "changed {:?}: added {:?}, removed {:?}, kept {:?}",
                     ptr, added, removed, kept
                 );
                 num_changed += 1;
             }
         }
-        eprintln!(
+        debug!(
             "iteration {}: {} global pointers changed",
             loop_count, num_changed
         );
@@ -1126,7 +1126,7 @@ fn run(tcx: TyCtxt) {
             break;
         }
     }
-    eprintln!("reached fixpoint in {} iterations", loop_count);
+    info!("reached fixpoint in {} iterations", loop_count);
 
     // Do final processing on each function.
     for &ldid in &all_fn_ldids {
@@ -1404,7 +1404,7 @@ fn run2<'tcx>(
         assert!(i < 100);
         func_reports.clear();
         all_rewrites.clear();
-        eprintln!("\n--- start rewriting ---");
+        info!("--- start rewriting ---");
 
         // Update non-rewritten items first.  This has two purposes.  First, it clears the
         // `new_keys()` lists, which we check at the end of the loop to see whether we've reached a
@@ -1536,7 +1536,7 @@ fn run2<'tcx>(
     let mut adt_reports = HashMap::<DefId, String>::new();
     for &def_id in gacx.adt_metadata.table.keys() {
         if gacx.foreign_mentioned_tys.contains(&def_id) {
-            eprintln!("Avoiding rewrite for foreign-mentioned type: {def_id:?}");
+            debug!("Avoiding rewrite for foreign-mentioned type: {def_id:?}");
             continue;
         }
         if fixed_defs.contains(&def_id) {
@@ -1587,7 +1587,7 @@ fn run2<'tcx>(
 
         // Print labeling and rewrites for the current function.
 
-        eprintln!("\nfinal labeling for {:?}:", name);
+        debug!("\nfinal labeling for {:?}:", name);
         let lcx1 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
         let lcx2 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
         for (local, decl) in mir.local_decls.iter_enumerated() {
@@ -1602,12 +1602,11 @@ fn run2<'tcx>(
             );
         }
 
-        eprintln!("\ntype assignment for {:?}:", name);
+        debug!("\ntype assignment for {:?}:", name);
         rewrite::dump_rewritten_local_tys(&acx, &asn, pointee_types, &mir, describe_local);
 
-        eprintln!();
         if let Some(report) = func_reports.remove(&ldid) {
-            eprintln!("{}", report);
+            debug!("{}", report);
         }
 
         info.acx_data.set(acx.into_data());
@@ -1673,7 +1672,7 @@ fn run2<'tcx>(
     }
 
     // Print results for `static` items.
-    eprintln!("\nfinal labeling for static items:");
+    debug!("\nfinal labeling for static items:");
     let lcx1 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
     let lcx2 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
     let mut static_dids = gacx.static_tys.keys().cloned().collect::<Vec<_>>();
@@ -1691,10 +1690,10 @@ fn run2<'tcx>(
             &gasn.flags,
         );
     }
-    eprintln!("\n{statics_report}");
+    debug!("\n{statics_report}");
 
     // Print results for ADTs and fields
-    eprintln!("\nfinal labeling for fields:");
+    debug!("\nfinal labeling for fields:");
     let mut field_dids = gacx.field_ltys.keys().cloned().collect::<Vec<_>>();
     field_dids.sort();
     for did in field_dids {
@@ -1704,7 +1703,7 @@ fn run2<'tcx>(
         if pid != PointerId::NONE {
             let ty_perms = gasn.perms[pid];
             let ty_flags = gasn.flags[pid];
-            eprintln!("{name:}: ({pid}) perms = {ty_perms:?}, flags = {ty_flags:?}");
+            debug!("{name:}: ({pid}) perms = {ty_perms:?}, flags = {ty_flags:?}");
         }
 
         // Emit annotations for fields
@@ -1739,7 +1738,7 @@ fn run2<'tcx>(
     adt_dids.sort();
     for did in adt_dids {
         if let Some(report) = adt_reports.remove(&did) {
-            eprintln!("\n{}", report);
+            debug!("\n{}", report);
         }
     }
 
@@ -1778,17 +1777,17 @@ fn run2<'tcx>(
     // ----------------------------------
 
     // Report errors that were caught previously
-    eprintln!("\nerror details:");
+    debug!("\nerror details:");
     for ldid in tcx.hir().body_owners() {
         if let Some(detail) = gacx.fns_failed.get(&ldid.to_def_id()) {
             if !detail.has_backtrace() {
                 continue;
             }
-            eprintln!("\nerror in {:?}:\n{}", ldid, detail.to_string_full());
+            debug!("\nerror in {:?}:{}", ldid, detail.to_string_full());
         }
     }
 
-    eprintln!("\nerror summary:");
+    debug!("\nerror summary:");
     fn sorted_def_ids(it: impl IntoIterator<Item = DefId>) -> Vec<DefId> {
         let mut v = it.into_iter().collect::<Vec<_>>();
         v.sort();
@@ -1802,27 +1801,27 @@ fn run2<'tcx>(
             Some(detail) => detail.to_string_short(),
             None => "(no panic)".into(),
         };
-        eprintln!("analysis of {def_id:?} failed: {flags:?}, {detail_str}");
+        debug!("analysis of {def_id:?} failed: {flags:?}, {detail_str}");
     }
 
     for def_id in sorted_def_ids(gacx.dont_rewrite_statics.keys()) {
         let flags = gacx.dont_rewrite_statics.get(def_id);
-        eprintln!("analysis of {def_id:?} failed: {flags:?}");
+        debug!("analysis of {def_id:?} failed: {flags:?}");
     }
 
     for def_id in sorted_def_ids(gacx.dont_rewrite_fields.keys()) {
         let flags = gacx.dont_rewrite_fields.get(def_id);
-        eprintln!("analysis of {def_id:?} failed: {flags:?}");
+        debug!("analysis of {def_id:?} failed: {flags:?}");
     }
 
-    eprintln!(
+    info!(
         "\nsaw errors in {} / {} functions",
         gacx.fns_failed.len(),
         all_fn_ldids.len()
     );
 
     if !known_perm_error_fns.is_empty() {
-        eprintln!(
+        info!(
             "saw permission errors in {} known fns",
             known_perm_error_fns.len()
         );
@@ -2184,7 +2183,7 @@ fn print_labeling_for_var<'tcx>(
             perms[lty.label]
         }
     });
-    eprintln!("{}: addr_of = {:?}, type = {:?}", desc, addr_of1, ty1);
+    debug!("{}: addr_of = {:?}, type = {:?}", desc, addr_of1, ty1);
 
     let addr_of2 = flags[addr_of_ptr];
     let ty2 = lcx2.relabel(lty, &mut |lty| {
@@ -2194,14 +2193,14 @@ fn print_labeling_for_var<'tcx>(
             flags[lty.label]
         }
     });
-    eprintln!(
+    debug!(
         "{}: addr_of flags = {:?}, type flags = {:?}",
         desc, addr_of2, ty2
     );
 
     let addr_of3 = addr_of_ptr;
     let ty3 = lty;
-    eprintln!("{}: addr_of = {:?}, type = {:?}", desc, addr_of3, ty3);
+    debug!("{}: addr_of = {:?}, type = {:?}", desc, addr_of3, ty3);
 }
 
 fn print_function_pointee_types<'tcx>(
@@ -2210,9 +2209,9 @@ fn print_function_pointee_types<'tcx>(
     mir: &Body<'tcx>,
     pointee_types: PointerTable<PointeeTypes<'tcx>>,
 ) {
-    eprintln!("\npointee types for {}", name);
+    debug!("\npointee types for {}", name);
     for (local, decl) in mir.local_decls.iter_enumerated() {
-        eprintln!(
+        debug!(
             "{:?} ({}): addr_of = {:?}, type = {:?}",
             local,
             describe_local(acx.tcx(), decl),
@@ -2235,7 +2234,7 @@ fn print_function_pointee_types<'tcx>(
             if tys.ltys.is_empty() && !tys.incomplete {
                 continue;
             }
-            eprintln!(
+            debug!(
                 "  pointer {:?}: {:?}{}",
                 ptr,
                 tys.ltys,

c2rust-analyze/src/borrowck/def_use.rs

@@ -1,4 +1,5 @@
 use crate::borrowck::atoms::{AllFacts, AtomMaps, Loan, Path, SubPoint};
+use log::debug;
 use rustc_middle::mir::visit::{
     MutatingUseContext, NonMutatingUseContext, NonUseContext, PlaceContext, Visitor,
 };
@@ -96,7 +97,7 @@ struct DefUseVisitor<'tcx, 'a> {
 impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {
     fn visit_place(&mut self, place: &Place<'tcx>, context: PlaceContext, location: Location) {
         self.super_place(place, context, location);
-        eprintln!(
+        debug!(
             "visit place {:?} with context {:?} = {:?} at {:?}",
             place,
             context,
@@ -132,7 +133,7 @@ impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {
     }
 
     fn visit_local(&mut self, local: Local, context: PlaceContext, location: Location) {
-        eprintln!(
+        debug!(
             "visit local {:?} with context {:?} = {:?} at {:?}",
             local,
             context,
@@ -157,7 +158,7 @@ impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {
 
     fn visit_statement(&mut self, stmt: &Statement<'tcx>, location: Location) {
         self.super_statement(stmt, location);
-        eprintln!("visit stmt {:?} at {:?}", stmt, location);
+        debug!("visit stmt {:?} at {:?}", stmt, location);
 
         if let StatementKind::StorageDead(local) = stmt.kind {
             // Observed: `StorageDead` emits `path_moved_at_base` at the `Mid` point.
@@ -194,7 +195,7 @@ impl<'tcx> LoanInvalidatedAtVisitor<'tcx, '_> {
         context: PlaceContext,
         location: Location,
     ) {
-        eprintln!(
+        debug!(
             "access loan {:?} (kind {:?}) at location {:?} (context {:?} = {:?})",
             loan,
             borrow_kind,
@@ -223,7 +224,7 @@ impl<'tcx> LoanInvalidatedAtVisitor<'tcx, '_> {
 impl<'tcx> Visitor<'tcx> for LoanInvalidatedAtVisitor<'tcx, '_> {
     fn visit_place(&mut self, place: &Place<'tcx>, context: PlaceContext, location: Location) {
         //self.super_place(place, context, location);
-        eprintln!(
+        debug!(
             "loan_invalidated_at: visit place {:?} with context {:?} = {:?} at {:?}",
             place,
             context,
@@ -260,7 +261,7 @@ impl<'tcx> Visitor<'tcx> for LoanInvalidatedAtVisitor<'tcx, '_> {
     }
 
     fn visit_local(&mut self, local: Local, context: PlaceContext, location: Location) {
-        eprintln!(
+        debug!(
             "loan_invalidated_at: visit local {:?} with context {:?} = {:?} at {:?}",
             local,
             context,