From 16e4650d8d2a9a9dff3a207ab44c36801e808268 Mon Sep 17 00:00:00 2001
From: Jonathan Locke <lockathan@gmail.com>
Date: Mon, 19 Aug 2019 15:12:56 +0100
Subject: [PATCH] CORDA-3060: Improve Notary logging from an operator/admins
 point of view

Added logging during the processing steps of the PersistentUniqunessProvider and the RaftUniquenessProvider
Bumped up logging level of existing logging statements that occur while processing from debug to info
Added mention of txId to logging statements to enable a request to be traced through from the time it is added to the queue to the time that it is committed.
---
 .../transactions/PersistentUniquenessProvider.kt      | 11 ++++++-----
 .../experimental/raft/RaftUniquenessProvider.kt       |  5 +++--
 2 files changed, 9 insertions(+), 7 deletions(-)

diff --git a/node/src/main/kotlin/net/corda/node/services/transactions/PersistentUniquenessProvider.kt b/node/src/main/kotlin/net/corda/node/services/transactions/PersistentUniquenessProvider.kt
index 85b054aa6b..764608d540 100644
--- a/node/src/main/kotlin/net/corda/node/services/transactions/PersistentUniquenessProvider.kt
+++ b/node/src/main/kotlin/net/corda/node/services/transactions/PersistentUniquenessProvider.kt
@@ -181,6 +181,7 @@ class PersistentUniquenessProvider(val clock: Clock, val database: CordaPersiste
         val future = openFuture<UniquenessProvider.Result>()
         val request = CommitRequest(states, txId, callerIdentity, requestSignature, timeWindow, references, future)
         requestQueue.put(request)
+        log.debug { "Request added to queue. txId: $txId" }
         return future
     }
 
@@ -246,18 +247,18 @@ class PersistentUniquenessProvider(val clock: Clock, val database: CordaPersiste
     private fun handleReferenceConflicts(txId: SecureHash, conflictingStates: LinkedHashMap<StateRef, StateConsumptionDetails>) {
         if (!previouslyCommitted(txId)) {
             val conflictError = NotaryError.Conflict(txId, conflictingStates)
-            log.debug { "Failure, input states already committed: ${conflictingStates.keys}" }
+            log.info("Failure, input states already committed: ${conflictingStates.keys}. txId: $txId")
             throw NotaryInternalException(conflictError)
         }
-        log.debug { "Transaction $txId already notarised" }
+        log.info("Transaction $txId already notarised. txId: $txId")
     }
 
     private fun handleConflicts(txId: SecureHash, conflictingStates: LinkedHashMap<StateRef, StateConsumptionDetails>) {
         if (isConsumedByTheSameTx(txId.sha256(), conflictingStates)) {
-            log.debug { "Transaction $txId already notarised" }
+            log.info("Transaction $txId already notarised. txId: $txId")
             return
         } else {
-            log.debug { "Failure, input states already committed: ${conflictingStates.keys}" }
+            log.info("Failure, input states already committed: ${conflictingStates.keys}. txId: $txId")
             val conflictError = NotaryError.Conflict(txId, conflictingStates)
             throw NotaryInternalException(conflictError)
         }
@@ -276,7 +277,7 @@ class PersistentUniquenessProvider(val clock: Clock, val database: CordaPersiste
             }
             val session = currentDBSession()
             session.persist(CommittedTransaction(txId.toString()))
-            log.debug { "Successfully committed all input states: $states" }
+            log.info("Successfully committed all input states: $states. txId: $txId")
         } else {
             throw NotaryInternalException(outsideTimeWindowError)
         }
diff --git a/node/src/main/kotlin/net/corda/notary/experimental/raft/RaftUniquenessProvider.kt b/node/src/main/kotlin/net/corda/notary/experimental/raft/RaftUniquenessProvider.kt
index 364477494e..5c43294eed 100644
--- a/node/src/main/kotlin/net/corda/notary/experimental/raft/RaftUniquenessProvider.kt
+++ b/node/src/main/kotlin/net/corda/notary/experimental/raft/RaftUniquenessProvider.kt
@@ -211,7 +211,7 @@ class RaftUniquenessProvider(
             timeWindow: TimeWindow?,
             references: List<StateRef>
     ): CordaFuture<UniquenessProvider.Result> {
-        log.debug { "Attempting to commit input states: ${states.joinToString()}" }
+        log.debug { "Attempting to commit input states: ${states.joinToString()} for txId: $txId" }
         val commitCommand = CommitTransaction(
                 states,
                 txId,
@@ -223,9 +223,10 @@ class RaftUniquenessProvider(
         val future = openFuture<UniquenessProvider.Result>()
         client.submit(commitCommand).thenAccept { commitError ->
             val result = if (commitError != null) {
+                log.info("Error occurred while notarising $txId: $commitError")
                 UniquenessProvider.Result.Failure(commitError)
             } else {
-                log.debug { "All input states of transaction $txId have been committed" }
+                log.info("All input states of transaction $txId have been committed")
                 UniquenessProvider.Result.Success
             }
             future.set(result)