GRIN/grin-node
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Replace logging backend to log4rs and add log rotation (#1789)

Browse Source 
* Replace logging backend to flexi-logger and add log rotation
* Changed flexi_logger to log4rs
* Disable logging level filtering in Root logger
* Support different logging levels for file and stdout
* Don't log messages from modules other than Grin-related
* Fix formatting
* Place backed up compressed log copies into log file directory
* Increase default log file size to 16 MiB
* Add comment to config file on log_max_size option
This commit is contained in:
eupn
2018-10-21 23:30:56 +03:00
committed by Ignotus Peverell
parent 0852b0c4cf
commit 1195071f5b
83 changed files with 582 additions and 897 deletions
Download Patch File Download Diff File Expand all files Collapse all files
chain/src/chain.rs
+11 -38
View File
@@ -38,7 +38,6 @@ use store;
use txhashset;
use types::{ChainAdapter, NoStatus, Options, Tip, TxHashSetRoots, TxHashsetWriteStatus};
use util::secp::pedersen::{Commitment, RangeProof};
use util::LOGGER;
/// Orphan pool size is limited by MAX_ORPHAN_SIZE
pub const MAX_ORPHAN_SIZE: usize = 200;
@@ -184,7 +183,6 @@ impl Chain {
let head = store.head()?;
debug!(
LOGGER,
"Chain init: {} @ {} [{}]",
head.total_difficulty.to_num(),
head.height,
@@ -261,7 +259,6 @@ impl Chain {
&self.orphans.add(orphan);
debug!(
LOGGER,
"process_block: orphan: {:?}, # orphans {}{}",
block_hash,
self.orphans.len(),
@@ -275,7 +272,6 @@ impl Chain {
}
ErrorKind::Unfit(ref msg) => {
debug!(
LOGGER,
"Block {} at {} is unfit at this time: {}",
b.hash(),
b.header.height,
@@ -285,7 +281,6 @@ impl Chain {
}
_ => {
info!(
LOGGER,
"Rejected block {} at {}: {:?}",
b.hash(),
b.header.height,
@@ -360,7 +355,6 @@ impl Chain {
// Is there an orphan in our orphans that we can now process?
loop {
trace!(
LOGGER,
"check_orphans: at {}, # orphans {}",
height,
self.orphans.len(),
@@ -373,7 +367,6 @@ impl Chain {
let orphans_len = orphans.len();
for (i, orphan) in orphans.into_iter().enumerate() {
debug!(
LOGGER,
"check_orphans: get block {} at {}{}",
orphan.block.hash(),
height,
@@ -402,7 +395,6 @@ impl Chain {
if initial_height != height {
debug!(
LOGGER,
"check_orphans: {} blocks accepted since height {}, remaining # orphans {}",
height - initial_height,
initial_height,
@@ -589,7 +581,6 @@ impl Chain {
txhashset: &txhashset::TxHashSet,
) -> Result<(), Error> {
debug!(
LOGGER,
"chain: validate_kernel_history: rewinding and validating kernel history (readonly)"
);
@@ -606,8 +597,8 @@ impl Chain {
})?;
debug!(
LOGGER,
"chain: validate_kernel_history: validated kernel root on {} headers", count,
"chain: validate_kernel_history: validated kernel root on {} headers",
count,
);
Ok(())
@@ -682,10 +673,7 @@ impl Chain {
self.validate_kernel_history(&header, &txhashset)?;
// all good, prepare a new batch and update all the required records
debug!(
LOGGER,
"chain: txhashset_write: rewinding a 2nd time (writeable)"
);
debug!("chain: txhashset_write: rewinding a 2nd time (writeable)");
let mut batch = self.store.batch()?;
@@ -709,10 +697,7 @@ impl Chain {
Ok(())
})?;
debug!(
LOGGER,
"chain: txhashset_write: finished validating and rebuilding"
);
debug!("chain: txhashset_write: finished validating and rebuilding");
status.on_save();
@@ -727,10 +712,7 @@ impl Chain {
// Commit all the changes to the db.
batch.commit()?;
debug!(
LOGGER,
"chain: txhashset_write: finished committing the batch (head etc.)"
);
debug!("chain: txhashset_write: finished committing the batch (head etc.)");
// Replace the chain txhashset with the newly built one.
{
@@ -738,10 +720,7 @@ impl Chain {
*txhashset_ref = txhashset;
}
debug!(
LOGGER,
"chain: txhashset_write: replaced our txhashset with the new one"
);
debug!("chain: txhashset_write: replaced our txhashset with the new one");
// Check for any orphan blocks and process them based on the new chain state.
self.check_orphans(header.height + 1);
@@ -763,14 +742,11 @@ impl Chain {
/// therefore be called judiciously.
pub fn compact(&self) -> Result<(), Error> {
if self.archive_mode {
debug!(
LOGGER,
"Blockchain compaction disabled, node running in archive mode."
);
debug!("Blockchain compaction disabled, node running in archive mode.");
return Ok(());
}
debug!(LOGGER, "Starting blockchain compaction.");
debug!("Starting blockchain compaction.");
// Compact the txhashset via the extension.
{
let mut txhashset = self.txhashset.write();
@@ -785,7 +761,7 @@ impl Chain {
// Now check we can still successfully validate the chain state after
// compacting, shouldn't be necessary once all of this is well-oiled
debug!(LOGGER, "Validating state after compaction.");
debug!("Validating state after compaction.");
self.validate(true)?;
// we need to be careful here in testing as 20 blocks is not that long
@@ -798,7 +774,6 @@ impl Chain {
}
debug!(
LOGGER,
"Compaction remove blocks older than {}.",
head.height - horizon
);
@@ -831,7 +806,7 @@ impl Chain {
}
}
batch.commit()?;
debug!(LOGGER, "Compaction removed {} blocks, done.", count);
debug!("Compaction removed {} blocks, done.", count);
Ok(())
}
@@ -1052,7 +1027,6 @@ fn setup_head(
if header.height > 0 && extension.batch.get_block_sums(&header.hash()).is_err()
{
debug!(
LOGGER,
"chain: init: building (missing) block sums for {} @ {}",
header.height,
header.hash()
@@ -1073,7 +1047,6 @@ fn setup_head(
}
debug!(
LOGGER,
"chain: init: rewinding and validating before we start... {} at {}",
header.hash(),
header.height,
@@ -1110,7 +1083,7 @@ fn setup_head(
// Save the block_sums to the db for use later.
batch.save_block_sums(&genesis.hash(), &BlockSums::default())?;
info!(LOGGER, "chain: init: saved genesis: {:?}", genesis.hash());
info!("chain: init: saved genesis: {:?}", genesis.hash());
}
Err(e) => return Err(ErrorKind::StoreErr(e, "chain init load head".to_owned()))?,
};
chain/src/lib.rs
+1 -1
View File
@@ -30,7 +30,7 @@ extern crate serde;
#[macro_use]
extern crate serde_derive;
#[macro_use]
extern crate slog;
extern crate log;
extern crate chrono;
extern crate failure;
#[macro_use]
chain/src/pipe.rs
+10 -21
View File
@@ -35,7 +35,6 @@ use grin_store;
use store;
use txhashset;
use types::{Options, Tip};
use util::LOGGER;
/// Contextual information required to process a new block and either reject or
/// accept it.
@@ -71,7 +70,6 @@ pub fn process_block(b: &Block, ctx: &mut BlockContext) -> Result<Option<Tip>, E
// spend resources reading the full block when its header is invalid
debug!(
LOGGER,
"pipe: process_block {} at {} with {} inputs, {} outputs, {} kernels",
b.hash(),
b.header.height,
@@ -168,7 +166,6 @@ pub fn process_block(b: &Block, ctx: &mut BlockContext) -> Result<Option<Tip>, E
})?;
trace!(
LOGGER,
"pipe: process_block: {} at {} is valid, save and append.",
b.hash(),
b.header.height,
@@ -190,7 +187,6 @@ pub fn sync_block_headers(
) -> Result<Option<Tip>, Error> {
if let Some(header) = headers.first() {
debug!(
LOGGER,
"pipe: sync_block_headers: {} headers from {} at {}",
headers.len(),
header.hash(),
@@ -251,7 +247,6 @@ pub fn sync_block_headers(
/// it.
pub fn process_block_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), Error> {
debug!(
LOGGER,
"pipe: process_block_header: {} at {}",
header.hash(),
header.height,
@@ -356,8 +351,8 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E
// check version, enforces scheduled hard fork
if !consensus::valid_header_version(header.height, header.version) {
error!(
LOGGER,
"Invalid block header version received ({}), maybe update Grin?", header.version
"Invalid block header version received ({}), maybe update Grin?",
header.version
);
return Err(ErrorKind::InvalidBlockVersion(header.version).into());
}
@@ -378,8 +373,8 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E
let edge_bits = header.pow.edge_bits();
if !(ctx.pow_verifier)(header, edge_bits).is_ok() {
error!(
LOGGER,
"pipe: error validating header with cuckoo edge_bits {}", edge_bits
"pipe: error validating header with cuckoo edge_bits {}",
edge_bits
);
return Err(ErrorKind::InvalidPow.into());
}
@@ -434,7 +429,6 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E
let next_header_info = consensus::next_difficulty(header.height, diff_iter);
if target_difficulty != next_header_info.difficulty {
info!(
LOGGER,
"validate_header: header target difficulty {} != {}",
target_difficulty.to_num(),
next_header_info.difficulty.to_num()
@@ -548,8 +542,8 @@ fn update_head(b: &Block, ctx: &BlockContext) -> Result<Option<Tip>, Error> {
.map_err(|e| ErrorKind::StoreErr(e, "pipe save body".to_owned()))?;
debug!(
LOGGER,
"pipe: head updated to {} at {}", tip.last_block_h, tip.height
"pipe: head updated to {} at {}",
tip.last_block_h, tip.height
);
Ok(Some(tip))
@@ -569,7 +563,7 @@ fn update_sync_head(bh: &BlockHeader, batch: &mut store::Batch) -> Result<(), Er
batch
.save_sync_head(&tip)
.map_err(|e| ErrorKind::StoreErr(e, "pipe save sync head".to_owned()))?;
debug!(LOGGER, "sync head {} @ {}", bh.hash(), bh.height);
debug!("sync head {} @ {}", bh.hash(), bh.height);
Ok(())
}
@@ -583,8 +577,8 @@ fn update_header_head(bh: &BlockHeader, ctx: &mut BlockContext) -> Result<Option
.map_err(|e| ErrorKind::StoreErr(e, "pipe save header head".to_owned()))?;
debug!(
LOGGER,
"pipe: header_head updated to {} at {}", tip.last_block_h, tip.height
"pipe: header_head updated to {} at {}",
tip.last_block_h, tip.height
);
Ok(Some(tip))
@@ -616,7 +610,6 @@ pub fn rewind_and_apply_fork(b: &Block, ext: &mut txhashset::Extension) -> Resul
let forked_header = ext.batch.get_block_header(&current)?;
trace!(
LOGGER,
"rewind_and_apply_fork @ {} [{}], was @ {} [{}]",
forked_header.height,
forked_header.hash(),
@@ -627,11 +620,7 @@ pub fn rewind_and_apply_fork(b: &Block, ext: &mut txhashset::Extension) -> Resul
// Rewind the txhashset state back to the block where we forked from the most work chain.
ext.rewind(&forked_header)?;
trace!(
LOGGER,
"rewind_and_apply_fork: blocks on fork: {:?}",
fork_hashes,
);
trace!("rewind_and_apply_fork: blocks on fork: {:?}", fork_hashes,);
// Now re-apply all blocks on this fork.
for (_, h) in fork_hashes {
chain/src/txhashset/txhashset.rs
+37 -79
View File
@@ -40,7 +40,7 @@ use grin_store::types::prune_noop;
use store::{Batch, ChainStore};
use txhashset::{RewindableKernelView, UTXOView};
use types::{Tip, TxHashSetRoots, TxHashsetWriteStatus};
use util::{file, secp_static, zip, LOGGER};
use util::{file, secp_static, zip};
const HEADERHASHSET_SUBDIR: &'static str = "header";
const TXHASHSET_SUBDIR: &'static str = "txhashset";
@@ -328,7 +328,7 @@ where
// we explicitly rewind the extension.
let header = batch.head_header()?;
trace!(LOGGER, "Starting new txhashset (readonly) extension.");
trace!("Starting new txhashset (readonly) extension.");
let res = {
let mut extension = Extension::new(trees, &batch, header);
@@ -340,14 +340,14 @@ where
inner(&mut extension)
};
trace!(LOGGER, "Rollbacking txhashset (readonly) extension.");
trace!("Rollbacking txhashset (readonly) extension.");
trees.header_pmmr_h.backend.discard();
trees.output_pmmr_h.backend.discard();
trees.rproof_pmmr_h.backend.discard();
trees.kernel_pmmr_h.backend.discard();
trace!(LOGGER, "TxHashSet (readonly) extension done.");
trace!("TxHashSet (readonly) extension done.");
res
}
@@ -423,7 +423,7 @@ where
// index saving can be undone
let child_batch = batch.child()?;
{
trace!(LOGGER, "Starting new txhashset extension.");
trace!("Starting new txhashset extension.");
// TODO - header_mmr may be out ahead via the header_head
// TODO - do we need to handle this via an explicit rewind on the header_mmr?
@@ -436,10 +436,7 @@ where
match res {
Err(e) => {
debug!(
LOGGER,
"Error returned, discarding txhashset extension: {}", e
);
debug!("Error returned, discarding txhashset extension: {}", e);
trees.header_pmmr_h.backend.discard();
trees.output_pmmr_h.backend.discard();
trees.rproof_pmmr_h.backend.discard();
@@ -448,13 +445,13 @@ where
}
Ok(r) => {
if rollback {
trace!(LOGGER, "Rollbacking txhashset extension. sizes {:?}", sizes);
trace!("Rollbacking txhashset extension. sizes {:?}", sizes);
trees.header_pmmr_h.backend.discard();
trees.output_pmmr_h.backend.discard();
trees.rproof_pmmr_h.backend.discard();
trees.kernel_pmmr_h.backend.discard();
} else {
trace!(LOGGER, "Committing txhashset extension. sizes {:?}", sizes);
trace!("Committing txhashset extension. sizes {:?}", sizes);
child_batch.commit()?;
trees.header_pmmr_h.backend.sync()?;
trees.output_pmmr_h.backend.sync()?;
@@ -466,7 +463,7 @@ where
trees.kernel_pmmr_h.last_pos = sizes.3;
}
trace!(LOGGER, "TxHashSet extension done.");
trace!("TxHashSet extension done.");
Ok(r)
}
}
@@ -497,7 +494,7 @@ where
// index saving can be undone
let child_batch = batch.child()?;
{
trace!(LOGGER, "Starting new txhashset sync_head extension.");
trace!("Starting new txhashset sync_head extension.");
let pmmr = DBPMMR::at(&mut trees.sync_pmmr_h.backend, trees.sync_pmmr_h.last_pos);
let mut extension = HeaderExtension::new(pmmr, &child_batch, header);
@@ -510,31 +507,23 @@ where
match res {
Err(e) => {
debug!(
LOGGER,
"Error returned, discarding txhashset sync_head extension: {}", e
"Error returned, discarding txhashset sync_head extension: {}",
e
);
trees.sync_pmmr_h.backend.discard();
Err(e)
}
Ok(r) => {
if rollback {
trace!(
LOGGER,
"Rollbacking txhashset sync_head extension. size {:?}",
size
);
trace!("Rollbacking txhashset sync_head extension. size {:?}", size);
trees.sync_pmmr_h.backend.discard();
} else {
trace!(
LOGGER,
"Committing txhashset sync_head extension. size {:?}",
size
);
trace!("Committing txhashset sync_head extension. size {:?}", size);
child_batch.commit()?;
trees.sync_pmmr_h.backend.sync()?;
trees.sync_pmmr_h.last_pos = size;
}
trace!(LOGGER, "TxHashSet sync_head extension done.");
trace!("TxHashSet sync_head extension done.");
Ok(r)
}
}
@@ -564,7 +553,7 @@ where
// index saving can be undone
let child_batch = batch.child()?;
{
trace!(LOGGER, "Starting new txhashset header extension.");
trace!("Starting new txhashset header extension.");
let pmmr = DBPMMR::at(
&mut trees.header_pmmr_h.backend,
trees.header_pmmr_h.last_pos,
@@ -579,31 +568,23 @@ where
match res {
Err(e) => {
debug!(
LOGGER,
"Error returned, discarding txhashset header extension: {}", e
"Error returned, discarding txhashset header extension: {}",
e
);
trees.header_pmmr_h.backend.discard();
Err(e)
}
Ok(r) => {
if rollback {
trace!(
LOGGER,
"Rollbacking txhashset header extension. size {:?}",
size
);
trace!("Rollbacking txhashset header extension. size {:?}", size);
trees.header_pmmr_h.backend.discard();
} else {
trace!(
LOGGER,
"Committing txhashset header extension. size {:?}",
size
);
trace!("Committing txhashset header extension. size {:?}", size);
child_batch.commit()?;
trees.header_pmmr_h.backend.sync()?;
trees.header_pmmr_h.last_pos = size;
}
trace!(LOGGER, "TxHashSet header extension done.");
trace!("TxHashSet header extension done.");
Ok(r)
}
}
@@ -654,7 +635,6 @@ impl<'a> HeaderExtension<'a> {
/// Note the close relationship between header height and insertion index.
pub fn rewind(&mut self, header: &BlockHeader) -> Result<(), Error> {
debug!(
LOGGER,
"Rewind header extension to {} at {}",
header.hash(),
header.height
@@ -675,7 +655,7 @@ impl<'a> HeaderExtension<'a> {
/// Used when rebuilding the header MMR by reapplying all headers
/// including the genesis block header.
pub fn truncate(&mut self) -> Result<(), Error> {
debug!(LOGGER, "Truncating header extension.");
debug!("Truncating header extension.");
self.pmmr.rewind(0).map_err(&ErrorKind::TxHashSetErr)?;
Ok(())
}
@@ -689,7 +669,6 @@ impl<'a> HeaderExtension<'a> {
/// Requires *all* header hashes to be iterated over in ascending order.
pub fn rebuild(&mut self, head: &Tip, genesis: &BlockHeader) -> Result<(), Error> {
debug!(
LOGGER,
"About to rebuild header extension from {:?} to {:?}.",
genesis.hash(),
head.last_block_h,
@@ -712,7 +691,6 @@ impl<'a> HeaderExtension<'a> {
if header_hashes.len() > 0 {
debug!(
LOGGER,
"Re-applying {} headers to extension, from {:?} to {:?}.",
header_hashes.len(),
header_hashes.first().unwrap(),
@@ -995,10 +973,7 @@ impl<'a> Extension<'a> {
/// We need the hash of each sibling pos from the pos up to the peak
/// including the sibling leaf node which may have been removed.
pub fn merkle_proof(&self, output: &OutputIdentifier) -> Result<MerkleProof, Error> {
debug!(
LOGGER,
"txhashset: merkle_proof: output: {:?}", output.commit,
);
debug!("txhashset: merkle_proof: output: {:?}", output.commit,);
// then calculate the Merkle Proof based on the known pos
let pos = self.batch.get_output_pos(&output.commit)?;
let merkle_proof = self
@@ -1027,12 +1002,7 @@ impl<'a> Extension<'a> {
/// Rewinds the MMRs to the provided block, rewinding to the last output pos
/// and last kernel pos of that block.
pub fn rewind(&mut self, header: &BlockHeader) -> Result<(), Error> {
debug!(
LOGGER,
"Rewind to header {} at {}",
header.hash(),
header.height,
);
debug!("Rewind to header {} at {}", header.hash(), header.height,);
// We need to build bitmaps of added and removed output positions
// so we can correctly rewind all operations applied to the output MMR
@@ -1067,11 +1037,8 @@ impl<'a> Extension<'a> {
rewind_rm_pos: &Bitmap,
) -> Result<(), Error> {
debug!(
LOGGER,
"txhashset: rewind_to_pos: header {}, output {}, kernel {}",
header_pos,
output_pos,
kernel_pos,
header_pos, output_pos, kernel_pos,
);
self.header_pmmr
@@ -1191,7 +1158,6 @@ impl<'a> Extension<'a> {
}
debug!(
LOGGER,
"txhashset: validated the header {}, output {}, rproof {}, kernel {} mmrs, took {}s",
self.header_pmmr.unpruned_size(),
self.output_pmmr.unpruned_size(),
@@ -1270,22 +1236,22 @@ impl<'a> Extension<'a> {
/// Dumps the output MMR.
/// We use this after compacting for visual confirmation that it worked.
pub fn dump_output_pmmr(&self) {
debug!(LOGGER, "-- outputs --");
debug!("-- outputs --");
self.output_pmmr.dump_from_file(false);
debug!(LOGGER, "--");
debug!("--");
self.output_pmmr.dump_stats();
debug!(LOGGER, "-- end of outputs --");
debug!("-- end of outputs --");
}
/// Dumps the state of the 3 sum trees to stdout for debugging. Short
/// version only prints the Output tree.
pub fn dump(&self, short: bool) {
debug!(LOGGER, "-- outputs --");
debug!("-- outputs --");
self.output_pmmr.dump(short);
if !short {
debug!(LOGGER, "-- range proofs --");
debug!("-- range proofs --");
self.rproof_pmmr.dump(short);
debug!(LOGGER, "-- kernels --");
debug!("-- kernels --");
self.kernel_pmmr.dump(short);
}
}
@@ -1318,7 +1284,6 @@ impl<'a> Extension<'a> {
}
debug!(
LOGGER,
"txhashset: verified {} kernel signatures, pmmr size {}, took {}s",
kern_count,
self.kernel_pmmr.unpruned_size(),
@@ -1353,8 +1318,8 @@ impl<'a> Extension<'a> {
commits.clear();
proofs.clear();
debug!(
LOGGER,
"txhashset: verify_rangeproofs: verified {} rangeproofs", proof_count,
"txhashset: verify_rangeproofs: verified {} rangeproofs",
proof_count,
);
}
}
@@ -1370,13 +1335,12 @@ impl<'a> Extension<'a> {
commits.clear();
proofs.clear();
debug!(
LOGGER,
"txhashset: verify_rangeproofs: verified {} rangeproofs", proof_count,
"txhashset: verify_rangeproofs: verified {} rangeproofs",
proof_count,
);
}
debug!(
LOGGER,
"txhashset: verified {} rangeproofs, pmmr size {}, took {}s",
proof_count,
self.rproof_pmmr.unpruned_size(),
@@ -1452,10 +1416,7 @@ fn check_and_remove_files(txhashset_path: &PathBuf, header: &BlockHeader) -> Res
// Removing unexpected directories if needed
if !dir_difference.is_empty() {
debug!(
LOGGER,
"Unexpected folder(s) found in txhashset folder, removing."
);
debug!("Unexpected folder(s) found in txhashset folder, removing.");
for diff in dir_difference {
let diff_path = txhashset_path.join(diff);
file::delete(diff_path)?;
@@ -1492,7 +1453,6 @@ fn check_and_remove_files(txhashset_path: &PathBuf, header: &BlockHeader) -> Res
.collect();
if !difference.is_empty() {
debug!(
LOGGER,
"Unexpected file(s) found in txhashset subfolder {:?}, removing.",
&subdirectory_path
);
@@ -1520,10 +1480,8 @@ pub fn input_pos_to_rewind(
if head_header.height < block_header.height {
debug!(
LOGGER,
"input_pos_to_rewind: {} < {}, nothing to rewind",
head_header.height,
block_header.height
head_header.height, block_header.height
);
return Ok(Bitmap::create());
}