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

@@ -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<T: Into<PathBuf> + AsRef<Path>, Tree: 'static + Merkle
     offset: UnpaddedByteIndex,
     num_bytes: UnpaddedBytesAmount,
 ) -> Result<UnpaddedBytesAmount> {
+    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<T: Into<PathBuf> + AsRef<Path>, 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<T: Into<PathBuf> + AsRef<Path>, 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<T: std::io::Read>(
     source: T,
     piece_size: UnpaddedBytesAmount,
 ) -> Result<PieceInfo> {
-    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<T: std::io::Read>(
         )?;
 
         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<Path>,
     T: AsRef<Path>,
 {
+    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,
         <DefaultBinaryTree as MerkleTreeTrait>::Arity::to_usize(),
         get_base_tree_count::<Tree>(),
-    )
+    );
+
+    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<Path>,
     T: AsRef<Path>,
 {
+    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::<DefaultOctTree>(&t_aux.tree_r_last_config)?;
 
+    info!("validate_cache_for_precommit:finish");
     Ok(())
 }
 

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<Tree: MerkleTreeTrait>(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<Tree: MerkleTreeTrait>(cache_dir: &Path) -> Result<()> {
         deserialize(&aux_bytes)
     }?;
 
-    TemporaryAux::<Tree, DefaultPieceHasher>::clear_temp(t_aux)
+    let result = TemporaryAux::<Tree, DefaultPieceHasher>::clear_temp(t_aux);
+
+    info!("clear_cache:finish");
+
+    result
 }
 
 // Ensure that any associated cached data persisted is discarded.
 pub fn clear_caches<Tree: MerkleTreeTrait>(
     replicas: &BTreeMap<SectorId, PrivateReplicaInfo<Tree>>,
 ) -> Result<()> {
+    info!("clear_caches:start");
+
     for replica in replicas.values() {
         clear_cache::<Tree>(&replica.cache_dir.as_path())?;
     }
 
+    info!("clear_caches:finish");
+
     Ok(())
 }
 
@@ -327,6 +337,7 @@ pub fn generate_winning_post_sector_challenge<Tree: MerkleTreeTrait>(
     sector_set_size: u64,
     prover_id: Commitment,
 ) -> Result<Vec<u64>> {
+    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<Tree: MerkleTreeTrait>(
 
     let randomness_safe: <Tree::Hasher as Hasher>::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.

filecoin-proofs/src/api/seal.rs

@@ -56,7 +56,7 @@ where
     S: AsRef<Path>,
     T: AsRef<Path>,
 {
-    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<Path>,
     S: AsRef<Path>,
 {
-    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<T: AsRef<Path>, 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<Tree: 'static + MerkleTreeTrait>(
     )
     .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<Tree: 'static + MerkleTreeTrait>(
 /// * `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<Commitment> {
-    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<Tree: 'static + MerkleTreeTrait>(
     seed: Ticket,
     proof_vec: &[u8],
 ) -> Result<bool> {
+    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<Tree: 'static + MerkleTreeTrait>(
         &verifying_key,
     )?;
 
-    StackedCompound::verify(
+    let result = StackedCompound::verify(
         &compound_public_params,
         &public_inputs,
         &proof,
@@ -620,7 +634,10 @@ pub fn verify_seal<Tree: 'static + MerkleTreeTrait>(
                 .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<Tree: 'static + MerkleTreeTrait>(
     seeds: &[Ticket],
     proof_vecs: &[&[u8]],
 ) -> Result<bool> {
+    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<Tree: 'static + MerkleTreeTrait>(
         )?);
     }
 
-    StackedCompound::<Tree, DefaultPieceHasher>::batch_verify(
+    let result = StackedCompound::<Tree, DefaultPieceHasher>::batch_verify(
         &compound_public_params,
         &public_inputs,
         &proofs,
@@ -735,5 +753,8 @@ pub fn verify_batch_seal<Tree: 'static + MerkleTreeTrait>(
                 .expect("unknown sector size") as usize,
         },
     )
-    .map_err(Into::into)
+    .map_err(Into::into);
+
+    info!("verify_batch_seal:finish");
+    result
 }