Improve logging for a better traceability

archethic-foundation · Jul 9, 2021 · 1ee0a9c · 1ee0a9c
1 parent cb99252
commit 1ee0a9c
Show file tree

Hide file tree

Showing 5 changed files with 46 additions and 27 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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,23 +408,23 @@ 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
         )
 
         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)
         )
 
         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)
         )