From 96755e86f0c28b90fa13857c5fdd1a3eeb4b90e0 Mon Sep 17 00:00:00 2001 From: "Tobin C. Harding" Date: Fri, 19 Jun 2020 05:42:32 +0800 Subject: [PATCH] fix(filecoin-proofs): add logging to all public API functions (#1137) From the issue description: "FFI exposed functions should log when called and right before they return." Add logging to all the public functions (excl. public trait implementations) within the `api` module. Closes: #650 --- filecoin-proofs/src/api/mod.rs | 46 ++++++++++++++++++++++------ filecoin-proofs/src/api/post.rs | 21 +++++++++++-- filecoin-proofs/src/api/seal.rs | 53 +++++++++++++++++++++++---------- 3 files changed, 92 insertions(+), 28 deletions(-) diff --git a/filecoin-proofs/src/api/mod.rs b/filecoin-proofs/src/api/mod.rs index ae40bd0be..422edcda3 100644 --- a/filecoin-proofs/src/api/mod.rs +++ b/filecoin-proofs/src/api/mod.rs @@ -4,6 +4,7 @@ use std::path::{Path, PathBuf}; use anyhow::{ensure, Context, Result}; use bincode::deserialize; +use log::info; use merkletree::store::{DiskStore, LevelCacheStore, StoreConfig}; use storage_proofs::cache_key::CacheKey; use storage_proofs::hasher::Hasher; @@ -69,6 +70,8 @@ pub fn get_unsealed_range + AsRef, Tree: 'static + Merkle offset: UnpaddedByteIndex, num_bytes: UnpaddedBytesAmount, ) -> Result { + info!("get_unsealed_range:start"); + let f_in = File::open(&sealed_path) .with_context(|| format!("could not open sealed_path={:?}", sealed_path.as_ref()))?; @@ -77,7 +80,7 @@ pub fn get_unsealed_range + AsRef, Tree: 'static + Merkle let buf_f_out = BufWriter::new(f_out); - unseal_range::<_, _, _, Tree>( + let result = unseal_range::<_, _, _, Tree>( porep_config, cache_path, f_in, @@ -88,7 +91,10 @@ pub fn get_unsealed_range + AsRef, Tree: 'static + Merkle ticket, offset, num_bytes, - ) + ); + + info!("get_unsealed_range:finish"); + result } /// Unseals the sector read from `sealed_sector` and returns the bytes for a @@ -127,6 +133,7 @@ where W: Write, Tree: 'static + MerkleTreeTrait, { + info!("unseal_range:start"); ensure!(comm_d != [0; 32], "Invalid all zero commitment (comm_d)"); let comm_d = @@ -176,7 +183,10 @@ where let written = write_unpadded(unsealed, &mut unsealed_output, 0, num_bytes.into()) .context("write_unpadded failed")?; - Ok(UnpaddedBytesAmount(written as u64)) + let amount = UnpaddedBytesAmount(written as u64); + + info!("unseal_range:finish"); + Ok(amount) } /// Generates a piece commitment for the provided byte source. Returns an error @@ -191,7 +201,9 @@ pub fn generate_piece_commitment( source: T, piece_size: UnpaddedBytesAmount, ) -> Result { - measure_op(Operation::GeneratePieceCommitment, || { + info!("generate_piece_commitment:start"); + + let result = measure_op(Operation::GeneratePieceCommitment, || { ensure_piece_size(piece_size)?; // send the source through the preprocessor @@ -204,7 +216,10 @@ pub fn generate_piece_commitment( )?; PieceInfo::new(commitment, piece_size) - }) + }); + + info!("generate_piece_commitment:finish"); + result } /// Computes a NUL-byte prefix and/or suffix for `source` using the provided @@ -236,7 +251,9 @@ where R: Read, W: Write, { - measure_op(Operation::AddPiece, || { + info!("add_piece:start"); + + let result = measure_op(Operation::AddPiece, || { ensure_piece_size(piece_size)?; let source = std::io::BufReader::new(source); @@ -273,7 +290,10 @@ where let written = piece_alignment.left_bytes + piece_alignment.right_bytes + piece_size; Ok((PieceInfo::new(comm, n)?, written)) - }) + }); + + info!("add_piece:finish"); + result } fn ensure_piece_size(piece_size: UnpaddedBytesAmount) -> Result<()> { @@ -447,6 +467,8 @@ where R: AsRef, T: AsRef, { + info!("validate_cache_for_precommit_phase2:start"); + ensure!( replica_path.as_ref().exists(), "Missing replica: {}", @@ -468,11 +490,14 @@ where ); config.path = cache_path.as_ref().into(); - verify_store( + let result = verify_store( &config, ::Arity::to_usize(), get_base_tree_count::(), - ) + ); + + info!("validate_cache_for_precommit_phase2:finish"); + result } // Checks for the existence of the replica data and t_aux, which in @@ -486,6 +511,8 @@ where R: AsRef, T: AsRef, { + info!("validate_cache_for_precommit:start"); + // Verify that the replica exists and is not empty. ensure!( replica_path.as_ref().exists(), @@ -540,6 +567,7 @@ where )?; verify_level_cache_store::(&t_aux.tree_r_last_config)?; + info!("validate_cache_for_precommit:finish"); Ok(()) } diff --git a/filecoin-proofs/src/api/post.rs b/filecoin-proofs/src/api/post.rs index 49dd1dcff..9e064aa80 100644 --- a/filecoin-proofs/src/api/post.rs +++ b/filecoin-proofs/src/api/post.rs @@ -208,6 +208,8 @@ impl PublicReplicaInfo { // Ensure that any associated cached data persisted is discarded. pub fn clear_cache(cache_dir: &Path) -> Result<()> { + info!("clear_cache:start"); + let t_aux = { let f_aux_path = cache_dir.to_path_buf().join(CacheKey::TAux.to_string()); let aux_bytes = std::fs::read(&f_aux_path) @@ -216,17 +218,25 @@ pub fn clear_cache(cache_dir: &Path) -> Result<()> { deserialize(&aux_bytes) }?; - TemporaryAux::::clear_temp(t_aux) + let result = TemporaryAux::::clear_temp(t_aux); + + info!("clear_cache:finish"); + + result } // Ensure that any associated cached data persisted is discarded. pub fn clear_caches( replicas: &BTreeMap>, ) -> Result<()> { + info!("clear_caches:start"); + for replica in replicas.values() { clear_cache::(&replica.cache_dir.as_path())?; } + info!("clear_caches:finish"); + Ok(()) } @@ -327,6 +337,7 @@ pub fn generate_winning_post_sector_challenge( sector_set_size: u64, prover_id: Commitment, ) -> Result> { + info!("generate_winning_post_sector_challenge:start"); ensure!(sector_set_size != 0, "empty sector set is invalid"); ensure!( post_config.typ == PoStType::Winning, @@ -338,12 +349,16 @@ pub fn generate_winning_post_sector_challenge( let randomness_safe: ::Domain = as_safe_commitment(randomness, "randomness")?; - fallback::generate_sector_challenges( + let result = fallback::generate_sector_challenges( randomness_safe, post_config.sector_count, sector_set_size, prover_id_safe, - ) + ); + + info!("generate_winning_post_sector_challenge:finish"); + + result } /// Verifies a winning proof-of-spacetime. diff --git a/filecoin-proofs/src/api/seal.rs b/filecoin-proofs/src/api/seal.rs index 33db035de..f34e37d75 100644 --- a/filecoin-proofs/src/api/seal.rs +++ b/filecoin-proofs/src/api/seal.rs @@ -56,7 +56,7 @@ where S: AsRef, T: AsRef, { - info!("seal_pre_commit_phase1: start"); + info!("seal_pre_commit_phase1:start"); // Sanity check all input path types. ensure!( @@ -178,11 +178,14 @@ where config.clone(), )?; - Ok(SealPreCommitPhase1Output { + let out = SealPreCommitPhase1Output { labels, config, comm_d, - }) + }; + + info!("seal_pre_commit_phase1:finish"); + Ok(out) } #[allow(clippy::too_many_arguments)] @@ -196,7 +199,7 @@ where R: AsRef, S: AsRef, { - info!("seal_pre_commit_phase2: start"); + info!("seal_pre_commit_phase2:start"); // Sanity check all input path types. ensure!( @@ -302,7 +305,10 @@ where .write_all(&t_aux_bytes) .with_context(|| format!("could not write to file t_aux={:?}", t_aux_path))?; - Ok(SealPreCommitOutput { comm_r, comm_d }) + let out = SealPreCommitOutput { comm_r, comm_d }; + + info!("seal_pre_commit_phase2:finish"); + Ok(out) } #[allow(clippy::too_many_arguments)] @@ -419,16 +425,17 @@ pub fn seal_commit_phase1, Tree: 'static + MerkleTreeTrait>( )?; ensure!(sanity_check, "Invalid vanilla proof generated"); - info!("seal_commit_phase1:end"); - - Ok(SealCommitPhase1Output { + let out = SealCommitPhase1Output { vanilla_proofs, comm_r, comm_d, replica_id, seed, ticket, - }) + }; + + info!("seal_commit_phase1:finish"); + Ok(out) } #[allow(clippy::too_many_arguments)] @@ -519,9 +526,10 @@ pub fn seal_commit_phase2( ) .context("post-seal verification sanity check failed")?; - info!("seal_commit_phase2:end"); + let out = SealCommitOutput { proof: buf }; - Ok(SealCommitOutput { proof: buf }) + info!("seal_commit_phase2:finish"); + Ok(out) } /// Computes a sectors's `comm_d` given its pieces. @@ -531,7 +539,12 @@ pub fn seal_commit_phase2( /// * `porep_config` - this sector's porep config that contains the number of bytes in the sector. /// * `piece_infos` - the piece info (commitment and byte length) for each piece in this sector. pub fn compute_comm_d(sector_size: SectorSize, piece_infos: &[PieceInfo]) -> Result { - pieces::compute_comm_d(sector_size, piece_infos) + info!("compute_comm_d:start"); + + let result = pieces::compute_comm_d(sector_size, piece_infos); + + info!("compute_comm_d:finish"); + result } /// Verifies the output of some previously-run seal operation. @@ -557,6 +570,7 @@ pub fn verify_seal( seed: Ticket, proof_vec: &[u8], ) -> Result { + info!("verify_seal:start"); ensure!(comm_d_in != [0; 32], "Invalid all zero commitment (comm_d)"); ensure!(comm_r_in != [0; 32], "Invalid all zero commitment (comm_r)"); @@ -608,7 +622,7 @@ pub fn verify_seal( &verifying_key, )?; - StackedCompound::verify( + let result = StackedCompound::verify( &compound_public_params, &public_inputs, &proof, @@ -620,7 +634,10 @@ pub fn verify_seal( .expect("unknown sector size") as usize, }, ) - .map_err(Into::into) + .map_err(Into::into); + + info!("verify_seal:finish"); + result } /// Verifies a batch of outputs of some previously-run seal operations. @@ -646,6 +663,7 @@ pub fn verify_batch_seal( seeds: &[Ticket], proof_vecs: &[&[u8]], ) -> Result { + info!("verify_batch_seal:start"); ensure!(!comm_r_ins.is_empty(), "Cannot prove empty batch"); let l = comm_r_ins.len(); ensure!(l == comm_d_ins.len(), "Inconsistent inputs"); @@ -723,7 +741,7 @@ pub fn verify_batch_seal( )?); } - StackedCompound::::batch_verify( + let result = StackedCompound::::batch_verify( &compound_public_params, &public_inputs, &proofs, @@ -735,5 +753,8 @@ pub fn verify_batch_seal( .expect("unknown sector size") as usize, }, ) - .map_err(Into::into) + .map_err(Into::into); + + info!("verify_batch_seal:finish"); + result }