Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use log crate for debugging output in c2rust-analyze #1102

Merged
merged 1 commit into from
Nov 27, 2024
+149 −139
Merged

Use log crate for debugging output in c2rust-analyze #1102

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
85 changes: 42 additions & 43 deletions c2rust-analyze/src/analyze.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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 {
Expand All @@ -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;
}

Expand Down Expand Up @@ -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
);
Expand Down Expand Up @@ -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.
Expand All @@ -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);
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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
);
Expand All @@ -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 {
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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() {
Expand All @@ -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());
Expand Down Expand Up @@ -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<_>>();
Expand All @@ -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 {
Expand All @@ -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
Expand Down Expand Up @@ -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);
}
}

Expand Down Expand Up @@ -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();
Expand All @@ -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()
);
Expand Down Expand Up @@ -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| {
Expand All @@ -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>(
Expand All @@ -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),
Expand All @@ -2235,7 +2234,7 @@ fn print_function_pointee_types<'tcx>(
if tys.ltys.is_empty() && !tys.incomplete {
continue;
}
eprintln!(
debug!(
" pointer {:?}: {:?}{}",
ptr,
tys.ltys,
Expand Down
13 changes: 7 additions & 6 deletions c2rust-analyze/src/borrowck/def_use.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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,
};
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand All @@ -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.
Expand Down Expand Up @@ -194,7 +195,7 @@ impl<'tcx> LoanInvalidatedAtVisitor<'tcx, '_> {
context: PlaceContext,
location: Location,
) {
eprintln!(
debug!(
"access loan {:?} (kind {:?}) at location {:?} (context {:?} = {:?})",
loan,
borrow_kind,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand Down
Loading
Loading