From 5c5a8b640cf74d2015dc683b89fb63d01b0b915c Mon Sep 17 00:00:00 2001 From: ben-millar Date: Mon, 20 May 2024 14:17:37 +0100 Subject: [PATCH 1/5] CORE-8856 Adding lambda to suspendable function to trigger bug --- .../utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt index 29f1d964e34..5f3abc9e262 100644 --- a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt +++ b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt @@ -366,9 +366,9 @@ class UtxoFinalityFlowV1( } if (log.isDebugEnabled) { - log.debug( + log.debug { "Successfully notarized transaction $transactionId using notary $notary and received ${notarySignatures.size} signature(s)" - ) + } } return notarizedTransaction to notarySignatures From 062b53bc25133a68159f37e90bb3ac9c6f40314a Mon Sep 17 00:00:00 2001 From: ben-millar Date: Mon, 20 May 2024 14:44:07 +0100 Subject: [PATCH 2/5] CORE-8856 Added @RepeatedTest(100) annotation to test which exercises flaky behaviour --- .../applications/workers/smoketest/ledger/UtxoLedgerTests.kt | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/applications/workers/workers-smoketest/src/smokeTest/kotlin/net/corda/applications/workers/smoketest/ledger/UtxoLedgerTests.kt b/applications/workers/workers-smoketest/src/smokeTest/kotlin/net/corda/applications/workers/smoketest/ledger/UtxoLedgerTests.kt index ca16898aeea..dff5522c87a 100644 --- a/applications/workers/workers-smoketest/src/smokeTest/kotlin/net/corda/applications/workers/smoketest/ledger/UtxoLedgerTests.kt +++ b/applications/workers/workers-smoketest/src/smokeTest/kotlin/net/corda/applications/workers/smoketest/ledger/UtxoLedgerTests.kt @@ -25,6 +25,7 @@ import net.corda.e2etest.utilities.startRestFlow import net.corda.v5.crypto.SecureHash import org.assertj.core.api.Assertions.assertThat import org.junit.jupiter.api.BeforeAll +import org.junit.jupiter.api.RepeatedTest import org.junit.jupiter.api.Test import org.junit.jupiter.api.TestInfo import org.junit.jupiter.api.TestInstance @@ -109,7 +110,7 @@ class UtxoLedgerTests : ClusterReadiness by ClusterReadinessChecker() { } - @Test + @RepeatedTest(100) fun `Utxo Ledger - create a transaction containing states and finalize it then evolve it`(testInfo: TestInfo) { val idGenerator = TestRequestIdGenerator(testInfo) val input = "test input" From fbfb9a2a037553dbce6bb8a7b1c9579138295f9e Mon Sep 17 00:00:00 2001 From: ben-millar Date: Tue, 21 May 2024 10:43:44 +0100 Subject: [PATCH 3/5] CORE-8856 Moving log to info level to ensure it's being evaluated --- .../utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt | 3 ++- .../src/main/kotlin/net/corda/utilities/KotlinUtils.kt | 4 ++++ 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt index 5f3abc9e262..4e893542bf5 100644 --- a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt +++ b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt @@ -16,6 +16,7 @@ import net.corda.ledger.utxo.flow.impl.transaction.UtxoSignedTransactionInternal import net.corda.ledger.utxo.flow.impl.transaction.UtxoSignedTransactionWithDependencies import net.corda.sandbox.CordaSystemFlow import net.corda.utilities.debug +import net.corda.utilities.info import net.corda.utilities.trace import net.corda.v5.application.crypto.DigitalSignatureAndMetadata import net.corda.v5.application.flows.CordaInject @@ -122,7 +123,7 @@ class UtxoFinalityFlowV1( @Suspendable private fun persistUnverifiedTransaction() { persistenceService.persist(initialTransaction, TransactionStatus.UNVERIFIED) - log.debug { "Recorded transaction with initial signatures $transactionId" } + log.info { "Recorded transaction with initial signatures $transactionId" } } // Send initialTransaction, transferAdditionalSignatures, and filteredTransactionsAndSignatures diff --git a/libs/utilities/src/main/kotlin/net/corda/utilities/KotlinUtils.kt b/libs/utilities/src/main/kotlin/net/corda/utilities/KotlinUtils.kt index ede5800b18a..b5f3bdb50e6 100644 --- a/libs/utilities/src/main/kotlin/net/corda/utilities/KotlinUtils.kt +++ b/libs/utilities/src/main/kotlin/net/corda/utilities/KotlinUtils.kt @@ -25,6 +25,10 @@ inline fun Logger.debug(msg: () -> String) { if (isDebugEnabled) debug(msg()) } +inline fun Logger.info(msg: () -> String) { + info(msg()) +} + /** * Extension method for easier construction of [Duration]s in terms of integer days: `val twoDays = 2.days`. * @see Duration.ofDays From bdc132d5e8701fb39752b59b16d82c8d9d8f40d8 Mon Sep 17 00:00:00 2001 From: ben-millar Date: Tue, 28 May 2024 12:54:58 +0100 Subject: [PATCH 4/5] CORE-8856 Change every log in flow to info-level lambda log --- .../flows/finality/v1/UtxoFinalityFlowV1.kt | 51 +++++++++---------- 1 file changed, 25 insertions(+), 26 deletions(-) diff --git a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt index 4e893542bf5..c56446fe484 100644 --- a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt +++ b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt @@ -17,7 +17,6 @@ import net.corda.ledger.utxo.flow.impl.transaction.UtxoSignedTransactionWithDepe import net.corda.sandbox.CordaSystemFlow import net.corda.utilities.debug import net.corda.utilities.info -import net.corda.utilities.trace import net.corda.v5.application.crypto.DigitalSignatureAndMetadata import net.corda.v5.application.flows.CordaInject import net.corda.v5.application.messaging.FlowMessaging @@ -87,7 +86,7 @@ class UtxoFinalityFlowV1( val transferAdditionalSignatures = sessions.size > 1 addTransactionIdToFlowContext(flowEngine, transactionId) - log.trace("Starting finality flow for transaction: {}", transactionId) + log.info { "Starting finality flow for transaction: $transactionId" } verifyExistingSignatures(initialTransaction) verifyTransaction(initialTransaction) @@ -116,7 +115,7 @@ class UtxoFinalityFlowV1( val (notarizedTransaction, notarySignatures) = notarize(transaction, filteredTransactionsAndSignatures) persistNotarizedTransaction(notarizedTransaction) sendNotarySignaturesToCounterparties(notarySignatures) - log.trace("Finalisation of transaction {} has been finished.", transactionId) + log.info { "Finalisation of transaction $transactionId has been finished." } return notarizedTransaction } @@ -145,7 +144,7 @@ class UtxoFinalityFlowV1( if (initialTransaction.dependencies.isNotEmpty()) { flowEngine.subFlow(TransactionBackchainSenderFlow(initialTransaction.id, it)) } else { - log.trace { + log.info { "Transaction with id ${initialTransaction.id} has no dependencies so backchain resolution will not be performed." } } @@ -191,17 +190,17 @@ class UtxoFinalityFlowV1( is Payload.Failure<*> -> { val message = "Failed to receive signatures from ${session.counterparty} for transaction " + "$transactionId with message: ${signaturesPayload.message}" - log.warn(message) + log.info { message } persistInvalidTransaction(initialTransaction) throw CordaRuntimeException(message) } } - log.debug { "Received ${signatures.size} signature(s) from ${session.counterparty} for transaction $transactionId" } + log.info { "Received ${signatures.size} signature(s) from ${session.counterparty} for transaction $transactionId" } signatures.forEach { signature -> transaction = verifyAndAddSignature(transaction, signature) - log.debug { + log.info { "Added signature $signature by (key id) ${signature.by} from ${session.counterparty} for transaction " + transactionId } @@ -221,7 +220,7 @@ class UtxoFinalityFlowV1( transaction: UtxoSignedTransactionInternal, signaturesReceivedFromSessions: Map> ) { - log.debug { "Verifying all signatures for transaction $transactionId." } + log.info { "Verifying all signatures for transaction $transactionId." } try { transaction.verifySignatorySignatures() @@ -238,7 +237,7 @@ class UtxoFinalityFlowV1( val message = "Transaction $transactionId is missing signatures for signatories (key ids) " + "${e.missingSignatories.map { it.fullId() }}. The following counterparties provided signatures while finalizing " + "the transaction: $counterpartiesToSignatoriesMessage" - log.warn(message) + log.info { message } persistInvalidTransaction(transaction) throw TransactionMissingSignaturesException(transactionId, e.missingSignatories, message) } @@ -247,7 +246,7 @@ class UtxoFinalityFlowV1( @Suspendable private fun persistCounterpartySignatures(id: SecureHash, newSignatures: Set) { persistenceService.persistTransactionSignatures(id, newSignatures) - log.debug { "Recorded transaction with all parties' signatures $transactionId" } + log.info { "Recorded transaction with all parties' signatures $transactionId" } } @Suspendable @@ -261,9 +260,9 @@ class UtxoFinalityFlowV1( it !in signatures // These came from that party } }.toMap() - log.trace { "Sending updated signatures to counterparties for transaction $transactionId" } + log.info { "Sending updated signatures to counterparties for transaction $transactionId" } flowMessaging.sendAllMap(notSeenSignaturesBySessions) - log.debug { "Sent updated signatures to counterparties for transaction $transactionId" } + log.info { "Sent updated signatures to counterparties for transaction $transactionId" } } @Suppress("ThrowsCount") @@ -284,10 +283,10 @@ class UtxoFinalityFlowV1( ) // `log.trace {}` and `log.debug {}` are not used in this method due to a Quasar issue. if (log.isTraceEnabled) { - log.trace( + log.info { "Notarizing transaction $transactionId using pluggable notary client flow of " + - "${notarizationFlow::class.java.name} with notary $notary. Attempt number $attemptNumber" - ) + "${notarizationFlow::class.java.name} with notary $notary. Attempt number $attemptNumber" + } } flowEngine.subFlow(notarizationFlow) } @@ -300,16 +299,16 @@ class UtxoFinalityFlowV1( notarySignatures = notarize(++attemptNumber) break } catch (e: NotaryExceptionGeneral) { - log.warn( + log.info { "Received general error from notarization for transaction: ${transaction.id} on attempt: $attemptNumber. " + - "Error: ${e.message} Retrying notarisation." - ) + "Error: ${e.message} Retrying notarisation." + } continue } catch (e: NotaryExceptionUnknown) { - log.warn( + log.info { "Received unknown error from notarization for transaction: ${transaction.id} on attempt: $attemptNumber. " + - "Error: ${e.message} Retrying notarisation." - ) + "Error: ${e.message} Retrying notarisation." + } continue } catch (e: CordaRuntimeException) { val (message, failureReason) = if (e is NotaryExceptionFatal) { @@ -323,22 +322,22 @@ class UtxoFinalityFlowV1( Payload.Failure>(message, failureReason.value), sessions.toSet() ) - log.warn(message) + log.info{ message } throw e } } if (log.isTraceEnabled) { - log.trace( + log.info { "Received ${notarySignatures.size} signature(s) from notary $notary after requesting notarization of transaction " + - transactionId - ) + transactionId + } } if (notarySignatures.isEmpty()) { val message = "Notary $notary did not return any signatures after requesting notarization of transaction $transactionId" - log.warn(message) + log.info{ message } persistInvalidTransaction(transaction) flowMessaging.sendAll( Payload.Failure>( From 93b8fb2ae8febdffa6eef2d08db21230e84790ce Mon Sep 17 00:00:00 2001 From: ben-millar Date: Tue, 28 May 2024 16:51:45 +0100 Subject: [PATCH 5/5] CORE-8856 Fixed detekt issues --- .../impl/flows/finality/v1/UtxoFinalityFlowV1.kt | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt index c56446fe484..e1d4590b3f4 100644 --- a/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt +++ b/components/ledger/ledger-utxo-flow/src/main/kotlin/net/corda/ledger/utxo/flow/impl/flows/finality/v1/UtxoFinalityFlowV1.kt @@ -285,7 +285,7 @@ class UtxoFinalityFlowV1( if (log.isTraceEnabled) { log.info { "Notarizing transaction $transactionId using pluggable notary client flow of " + - "${notarizationFlow::class.java.name} with notary $notary. Attempt number $attemptNumber" + "${notarizationFlow::class.java.name} with notary $notary. Attempt number $attemptNumber" } } flowEngine.subFlow(notarizationFlow) @@ -301,13 +301,13 @@ class UtxoFinalityFlowV1( } catch (e: NotaryExceptionGeneral) { log.info { "Received general error from notarization for transaction: ${transaction.id} on attempt: $attemptNumber. " + - "Error: ${e.message} Retrying notarisation." + "Error: ${e.message} Retrying notarisation." } continue } catch (e: NotaryExceptionUnknown) { log.info { "Received unknown error from notarization for transaction: ${transaction.id} on attempt: $attemptNumber. " + - "Error: ${e.message} Retrying notarisation." + "Error: ${e.message} Retrying notarisation." } continue } catch (e: CordaRuntimeException) { @@ -322,7 +322,7 @@ class UtxoFinalityFlowV1( Payload.Failure>(message, failureReason.value), sessions.toSet() ) - log.info{ message } + log.info { message } throw e } } @@ -330,14 +330,14 @@ class UtxoFinalityFlowV1( if (log.isTraceEnabled) { log.info { "Received ${notarySignatures.size} signature(s) from notary $notary after requesting notarization of transaction " + - transactionId + transactionId } } if (notarySignatures.isEmpty()) { val message = "Notary $notary did not return any signatures after requesting notarization of transaction $transactionId" - log.info{ message } + log.info { message } persistInvalidTransaction(transaction) flowMessaging.sendAll( Payload.Failure>(