From 1ee0a9cb306f6b9e349805a7be9acacdcc9f2875 Mon Sep 17 00:00:00 2001 From: Samuel Date: Fri, 9 Jul 2021 16:21:32 +0200 Subject: [PATCH] Improve logging for a better traceability --- lib/archethic/contracts/loader.ex | 22 +++++++++++-- lib/archethic/mining/distributed_workflow.ex | 33 +++++++++++--------- lib/archethic/mining/standalone_workflow.ex | 2 +- lib/archethic/p2p/mem_table_loader.ex | 8 ++--- lib/archethic/transaction_chain.ex | 8 ++--- 5 files changed, 46 insertions(+), 27 deletions(-) diff --git a/lib/archethic/contracts/loader.ex b/lib/archethic/contracts/loader.ex index 54ce04872..9f9c034bf 100644 --- a/lib/archethic/contracts/loader.ex +++ b/lib/archethic/contracts/loader.ex @@ -69,7 +69,10 @@ defmodule ArchEthic.Contracts.Loader do {Worker, Contract.from_transaction!(tx)} ) - Logger.debug("Smart contract loaded", transaction: "#{type}@#{Base.encode16(address)}") + Logger.info("Smart contract loaded", + transaction_address: Base.encode16(address), + transaction_type: type + ) end _ -> @@ -87,12 +90,18 @@ defmodule ArchEthic.Contracts.Loader do ) when recipients != [] do Enum.each(recipients, fn contract_address -> + Logger.info("Execute transaction on contract #{Base.encode16(contract_address)}", + transaction_address: Base.encode16(tx_address), + transaction_type: tx_type + ) + case Worker.execute(contract_address, tx) do :ok -> TransactionLookup.add_contract_transaction(contract_address, tx_address, tx_timestamp) - Logger.debug("Transaction towards contract #{Base.encode16(contract_address)} ingested", - transaction: "#{tx_type}@#{Base.encode16(tx_address)}" + Logger.info("Transaction towards contract ingested", + transaction_address: Base.encode16(tx_address), + transaction_type: tx_type ) _ -> @@ -104,12 +113,18 @@ defmodule ArchEthic.Contracts.Loader do def load_transaction( %Transaction{ address: address, + type: type, validation_stamp: %ValidationStamp{recipients: recipients, timestamp: timestamp} }, true ) when recipients != [] do Enum.each(recipients, &TransactionLookup.add_contract_transaction(&1, address, timestamp)) + + Logger.info("Transaction towards contract ingested", + transaction_address: Base.encode16(address), + transaction_type: type + ) end def load_transaction(_tx, _), do: :ok @@ -122,6 +137,7 @@ defmodule ArchEthic.Contracts.Loader do case Registry.lookup(ContractRegistry, address) do [{pid, _}] -> DynamicSupervisor.terminate_child(ContractSupervisor, pid) + Logger.info("Stop smart contract at #{Base.encode16(address)}") _ -> :ok diff --git a/lib/archethic/mining/distributed_workflow.ex b/lib/archethic/mining/distributed_workflow.ex index 73865db74..362d9f68d 100644 --- a/lib/archethic/mining/distributed_workflow.ex +++ b/lib/archethic/mining/distributed_workflow.ex @@ -106,7 +106,10 @@ defmodule ArchEthic.Mining.DistributedWorkflow do Registry.register(WorkflowRegistry, tx.address, []) - Logger.info("Start mining", transaction_address: Base.encode16(tx.address), type: tx.type) + Logger.info("Start mining", + transaction_address: Base.encode16(tx.address), + transaction_type: tx.type + ) chain_storage_nodes = Replication.chain_storage_nodes_with_type(tx.address, tx.type) @@ -142,7 +145,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do end def handle_event(:enter, :idle, :idle, _data = %{context: %ValidationContext{transaction: tx}}) do - Logger.debug("Validation started", + Logger.info("Validation started", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -222,7 +225,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do } } ) do - Logger.debug("Retrieve transaction context", + Logger.info("Retrieve transaction context", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -254,7 +257,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do validation_nodes_view ) - Logger.debug("Transaction context retrieved", + Logger.info("Transaction context retrieved", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -270,7 +273,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do context: %ValidationContext{transaction: tx} } ) do - Logger.debug("Act as cross validator", + Logger.info("Act as cross validator", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -292,7 +295,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do :coordinator, _data = %{context: %ValidationContext{transaction: tx}} ) do - Logger.debug("Act as coordinator", + Logger.info("Act as coordinator", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -315,7 +318,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do } } ) do - Logger.debug("Aggregate mining context", + Logger.info("Aggregate mining context", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -332,7 +335,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do ) if ValidationContext.enough_confirmations?(new_context) do - Logger.debug("Create validation stamp", + Logger.info("Create validation stamp", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -372,7 +375,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do } } ) do - Logger.debug("Cross validation", + Logger.info("Cross validation", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -401,7 +404,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do :wait_cross_validation_stamps, _data = %{context: %ValidationContext{transaction: tx}} ) do - Logger.debug("Waiting cross validation stamps", + Logger.info("Waiting cross validation stamps", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -417,7 +420,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do context: context = %ValidationContext{transaction: tx} } ) do - Logger.debug("Add cross validation stamp", + Logger.info("Add cross validation stamp", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -544,7 +547,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do }, node_public_key ) do - Logger.debug( + Logger.info( "Send mining context to #{Node.endpoint(coordinator_node)}", transaction_type: tx_type, transaction_address: Base.encode16(tx_address) @@ -566,7 +569,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do validation_stamp: validation_stamp, full_replication_tree: replication_tree }) do - Logger.debug( + Logger.info( "Send validation stamp to #{cross_validation_nodes |> Enum.map(&:inet.ntoa(&1.ip)) |> Enum.join(", ")}", transaction_address: Base.encode16(tx_address), transaction_type: tx_type @@ -590,7 +593,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do |> P2P.distinct_nodes() |> Enum.reject(&(&1.last_public_key == Crypto.last_node_public_key())) - Logger.debug( + Logger.info( "Send cross validation stamps to #{nodes |> Enum.map(&Node.endpoint/1) |> Enum.join(", ")}", transaction_address: Base.encode16(tx_address), transaction_type: tx_type @@ -612,7 +615,7 @@ defmodule ArchEthic.Mining.DistributedWorkflow do worker_pid = self() - Logger.debug( + Logger.info( "Send validated transaction to #{storage_nodes |> Enum.map(fn {node, roles} -> "#{Node.endpoint(node)} as #{Enum.join(roles, ",")}" end) |> Enum.join(",")}", transaction_address: Base.encode16(tx.address), transaction_type: tx.type diff --git a/lib/archethic/mining/standalone_workflow.ex b/lib/archethic/mining/standalone_workflow.ex index ba3af7ae1..308be7a21 100644 --- a/lib/archethic/mining/standalone_workflow.ex +++ b/lib/archethic/mining/standalone_workflow.ex @@ -89,7 +89,7 @@ defmodule ArchEthic.Mining.StandaloneWorkflow do storage_nodes = ValidationContext.get_storage_nodes(context) - Logger.debug( + Logger.info( "Send validated transaction to #{storage_nodes |> Enum.map(fn {node, roles} -> "#{Node.endpoint(node)} as #{Enum.join(roles, ",")}" end) |> Enum.join(",")}", transaction_address: Base.encode16(validated_tx.address), transaction_type: validated_tx.type diff --git a/lib/archethic/p2p/mem_table_loader.ex b/lib/archethic/p2p/mem_table_loader.ex index bc7e4f157..34aff50f7 100644 --- a/lib/archethic/p2p/mem_table_loader.ex +++ b/lib/archethic/p2p/mem_table_loader.ex @@ -72,7 +72,7 @@ defmodule ArchEthic.P2P.MemTableLoader do }) do Logger.info("Loading transaction into P2P mem table", transaction_address: Base.encode16(address), - transaction_type: "node" + transaction_type: :node ) first_public_key = TransactionChain.get_first_public_key(previous_public_key) @@ -98,7 +98,7 @@ defmodule ArchEthic.P2P.MemTableLoader do MemTable.add_node(node) end - Logger.debug("Loaded into in memory p2p tables", node: Base.encode16(first_public_key)) + Logger.info("Node loaded into in memory p2p tables", node: Base.encode16(first_public_key)) end def load_transaction(%Transaction{ @@ -111,7 +111,7 @@ defmodule ArchEthic.P2P.MemTableLoader do }) do Logger.info("Loading transaction into P2P mem table", transaction_address: Base.encode16(address), - transaction_type: "node_shared_secrets" + transaction_type: :node_shared_secrets ) new_authorized_keys = Keys.list_authorized_keys(keys) @@ -134,7 +134,7 @@ defmodule ArchEthic.P2P.MemTableLoader do }) do Logger.info("Loading transaction into P2P mem table", transaction_address: Base.encode16(address), - transaction_type: "beacon_summary" + transaction_type: :beacon_summary ) {summary = %BeaconSummary{ diff --git a/lib/archethic/transaction_chain.ex b/lib/archethic/transaction_chain.ex index b65321ea8..a567b596c 100644 --- a/lib/archethic/transaction_chain.ex +++ b/lib/archethic/transaction_chain.ex @@ -384,7 +384,7 @@ defmodule ArchEthic.TransactionChain do if poi == proof_of_integrity([tx]) do true else - Logger.debug("Invalid proof of integrity", + Logger.error("Invalid proof of integrity", transaction_address: Base.encode16(tx.address), transaction_type: tx.type ) @@ -408,7 +408,7 @@ defmodule ArchEthic.TransactionChain do ]) do cond do proof_of_integrity([Transaction.to_pending(last_tx), prev_tx]) != poi -> - Logger.debug("Invalid proof of integrity", + Logger.error("Invalid proof of integrity", transaction_address: Base.encode16(last_tx.address), transaction_type: last_tx.type ) @@ -416,7 +416,7 @@ defmodule ArchEthic.TransactionChain do false Crypto.hash(previous_public_key) != previous_address -> - Logger.debug("Invalid previous public key", + Logger.error("Invalid previous public key", transaction_type: last_tx.type, transaction_address: Base.encode16(last_tx.address) ) @@ -424,7 +424,7 @@ defmodule ArchEthic.TransactionChain do false DateTime.diff(timestamp, previous_timestamp) < 0 -> - Logger.debug("Invalid timestamp", + Logger.error("Invalid timestamp", transaction_type: last_tx.type, transaction_address: Base.encode16(last_tx.address) )