[CORDA-1638]: Audit log of failed transactions MVP. (#3231)

core/src/main/kotlin/net/corda/core/flows/FinalityFlow.kt

@@ -4,6 +4,7 @@ import co.paralleluniverse.fibers.Suspendable
 import net.corda.core.crypto.isFulfilledBy
 import net.corda.core.identity.Party
 import net.corda.core.identity.groupAbstractPartyByWellKnownParty
+import net.corda.core.internal.pushToLoggingContext
 import net.corda.core.transactions.LedgerTransaction
 import net.corda.core.transactions.SignedTransaction
 import net.corda.core.utilities.ProgressTracker
@@ -51,17 +52,24 @@ class FinalityFlow(val transaction: SignedTransaction,
         //
         // Lookup the resolved transactions and use them to map each signed transaction to the list of participants.
         // Then send to the notary if needed, record locally and distribute.
+
+        transaction.pushToLoggingContext()
+        val commandDataTypes = transaction.tx.commands.map { it.value }.mapNotNull { it::class.qualifiedName }.distinct()
+        logger.info("Started finalization, commands are ${commandDataTypes.joinToString(", ", "[", "]")}.")
         val parties = getPartiesToSend(verifyTx())
         val notarised = notariseAndRecord()
 
         // Each transaction has its own set of recipients, but extra recipients get them all.
         progressTracker.currentStep = BROADCASTING
-        for (party in parties) {
-            if (!serviceHub.myInfo.isLegalIdentity(party)) {
-                val session = initiateFlow(party)
-                subFlow(SendTransactionFlow(session, notarised))
-            }
+        val recipients = parties.filterNot(serviceHub.myInfo::isLegalIdentity)
+        logger.info("Broadcasting transaction to parties ${recipients.map { it.name }.joinToString(", ", "[", "]")}.")
+        for (party in recipients) {
+            logger.info("Sending transaction to party ${party.name}.")
+            val session = initiateFlow(party)
+            subFlow(SendTransactionFlow(session, notarised))
+            logger.info("Party ${party.name} received the transaction.")
         }
+        logger.info("All parties received the transaction successfully.")
 
         return notarised
     }
@@ -73,9 +81,12 @@ class FinalityFlow(val transaction: SignedTransaction,
             val notarySignatures = subFlow(NotaryFlow.Client(transaction))
             transaction + notarySignatures
         } else {
+            logger.info("No need to notarise this transaction.")
             transaction
         }
+        logger.info("Recording transaction locally.")
         serviceHub.recordTransactions(notarised)
+        logger.info("Recorded transaction locally successfully.")
         return notarised
     }
 

core/src/main/kotlin/net/corda/core/flows/NotaryFlow.kt

@@ -9,6 +9,7 @@ import net.corda.core.identity.Party
 import net.corda.core.internal.FetchDataFlow
 import net.corda.core.internal.notary.generateSignature
 import net.corda.core.internal.notary.validateSignatures
+import net.corda.core.internal.pushToLoggingContext
 import net.corda.core.transactions.ContractUpgradeWireTransaction
 import net.corda.core.transactions.SignedTransaction
 import net.corda.core.transactions.WireTransaction
@@ -44,9 +45,12 @@ class NotaryFlow {
         @Suspendable
         @Throws(NotaryException::class)
         override fun call(): List<TransactionSignature> {
+            stx.pushToLoggingContext()
             val notaryParty = checkTransaction()
             progressTracker.currentStep = REQUESTING
+            logger.info("Sending transaction to notary: ${notaryParty.name}.")
             val response = notarise(notaryParty)
+            logger.info("Notary responded.")
             progressTracker.currentStep = VALIDATING
             return validateResponse(response, notaryParty)
         }

core/src/main/kotlin/net/corda/core/flows/ReceiveTransactionFlow.kt

@@ -3,6 +3,7 @@ package net.corda.core.flows
 import co.paralleluniverse.fibers.Suspendable
 import net.corda.core.contracts.*
 import net.corda.core.internal.ResolveTransactionsFlow
+import net.corda.core.internal.pushToLoggingContext
 import net.corda.core.node.StatesToRecord
 import net.corda.core.transactions.SignedTransaction
 import net.corda.core.utilities.unwrap
@@ -36,18 +37,25 @@ class ReceiveTransactionFlow @JvmOverloads constructor(private val otherSideSess
         } else {
             logger.trace("Receiving a transaction (but without checking the signatures) from ${otherSideSession.counterparty}")
         }
-
         val stx = otherSideSession.receive<SignedTransaction>().unwrap {
+            it.pushToLoggingContext()
+            logger.info("Received transaction acknowledgement request from party ${otherSideSession.counterparty.name}.")
             subFlow(ResolveTransactionsFlow(it, otherSideSession))
-            it.verify(serviceHub, checkSufficientSignatures)
-            it
+            logger.info("Transaction dependencies resolution completed.")
+            try {
+                it.verify(serviceHub, checkSufficientSignatures)
+                it
+            } catch (e: Exception) {
+                logger.warn("Transaction verification failed.")
+                throw e
+            }
         }
-
         if (checkSufficientSignatures) {
             // We should only send a transaction to the vault for processing if we did in fact fully verify it, and
             // there are no missing signatures. We don't want partly signed stuff in the vault.
-            logger.trace("Successfully received fully signed tx ${stx.id}, sending to the vault for processing")
+            logger.info("Successfully received fully signed tx. Sending it to the vault for processing.")
             serviceHub.recordTransactions(statesToRecord, setOf(stx))
+            logger.info("Successfully recorded received transaction locally.")
         }
         return stx
     }

core/src/main/kotlin/net/corda/core/internal/InternalUtils.kt

@@ -7,13 +7,19 @@ import com.google.common.hash.HashingInputStream
 import net.corda.core.cordapp.Cordapp
 import net.corda.core.cordapp.CordappConfig
 import net.corda.core.cordapp.CordappContext
-import net.corda.core.crypto.*
+import net.corda.core.crypto.Crypto
+import net.corda.core.crypto.DigitalSignature
+import net.corda.core.crypto.SecureHash
+import net.corda.core.crypto.SignedData
+import net.corda.core.crypto.sha256
+import net.corda.core.crypto.sign
 import net.corda.core.identity.CordaX500Name
 import net.corda.core.node.ServicesForResolution
 import net.corda.core.serialization.SerializationContext
 import net.corda.core.serialization.SerializedBytes
 import net.corda.core.serialization.deserialize
 import net.corda.core.serialization.serialize
+import net.corda.core.transactions.SignedTransaction
 import net.corda.core.transactions.TransactionBuilder
 import net.corda.core.transactions.WireTransaction
 import net.corda.core.utilities.OpaqueBytes
@@ -21,11 +27,15 @@ import org.bouncycastle.asn1.x500.X500Name
 import org.bouncycastle.asn1.x500.X500NameBuilder
 import org.bouncycastle.asn1.x500.style.BCStyle
 import org.slf4j.Logger
+import org.slf4j.MDC
 import rx.Observable
 import rx.Observer
 import rx.subjects.PublishSubject
 import rx.subjects.UnicastSubject
-import java.io.*
+import java.io.ByteArrayOutputStream
+import java.io.IOException
+import java.io.InputStream
+import java.io.OutputStream
 import java.lang.reflect.Field
 import java.lang.reflect.Modifier
 import java.math.BigDecimal
@@ -41,11 +51,23 @@ import java.nio.file.Paths
 import java.security.KeyPair
 import java.security.PrivateKey
 import java.security.PublicKey
-import java.security.cert.*
+import java.security.cert.CertPath
+import java.security.cert.CertPathValidator
+import java.security.cert.CertPathValidatorException
+import java.security.cert.PKIXCertPathValidatorResult
+import java.security.cert.PKIXParameters
+import java.security.cert.TrustAnchor
+import java.security.cert.X509Certificate
 import java.time.Duration
 import java.time.temporal.Temporal
 import java.util.*
-import java.util.Spliterator.*
+import java.util.Spliterator.DISTINCT
+import java.util.Spliterator.IMMUTABLE
+import java.util.Spliterator.NONNULL
+import java.util.Spliterator.ORDERED
+import java.util.Spliterator.SIZED
+import java.util.Spliterator.SORTED
+import java.util.Spliterator.SUBSIZED
 import java.util.concurrent.ExecutorService
 import java.util.concurrent.TimeUnit
 import java.util.stream.IntStream
@@ -459,3 +481,10 @@ val PublicKey.hash: SecureHash get() = encoded.sha256()
  * Extension method for providing a sumBy method that processes and returns a Long
  */
 fun <T> Iterable<T>.sumByLong(selector: (T) -> Long): Long = this.map { selector(it) }.sum()
+
+/**
+ * Ensures each log entry from the current thread will contain id of the transaction in the MDC.
+ */
+internal fun SignedTransaction.pushToLoggingContext() {
+    MDC.put("tx_id", id.toString())
+}

docs/source/changelog.rst

@@ -7,6 +7,8 @@ release, see :doc:`upgrade-notes`.
 Unreleased
 ==========
 
+* Improved audit trail for ``FinalityFlow`` and related sub-flows.
+
 * ``NodeStartup`` will now only print node's configuration if ``devMode`` is ``true``, avoiding the risk of printing passwords in a production setup.
 
 * SLF4J's MDC will now only be printed to the console if not empty. No more log lines ending with "{}".