commit e396a3dd12d1657cac892937a1b2f3ae4e3ef9f6
parent 7d905787737c9f931c90258af96ac8c8a4de80e8
Author: Antoine A <>
Date: Tue, 30 Jul 2024 21:09:13 +0200
nexus: fix test and improve logging
Diffstat:
9 files changed, 91 insertions(+), 73 deletions(-)
diff --git a/bank/src/main/kotlin/tech/libeufin/bank/api/CoreBankApi.kt b/bank/src/main/kotlin/tech/libeufin/bank/api/CoreBankApi.kt
@@ -111,7 +111,7 @@ private fun Routing.coreBankTokenApi(db: Database, cfg: BankConfig) {
Instant.MAX
} else {
try {
- logger.debug("Creating token with days duration: ${tokenDuration.toDays()}")
+ logger.debug { "Creating token with days duration: ${tokenDuration.toDays()}" }
creationTime.plus(tokenDuration)
} catch (e: Exception) {
throw badRequest("Bad token duration: ${e.message}")
diff --git a/common/src/main/kotlin/Cli.kt b/common/src/main/kotlin/Cli.kt
@@ -39,21 +39,6 @@ import org.slf4j.event.Level
private val logger: Logger = LoggerFactory.getLogger("libeufin-config")
-fun Throwable.fmt(): String = buildString {
- append(message ?: this@fmt::class.simpleName)
- var cause = cause
- while (cause != null) {
- append(": ")
- append(cause.message ?: cause::class.simpleName)
- cause = cause.cause
- }
-}
-
-fun Throwable.fmtLog(logger: Logger) {
- logger.error(this.fmt())
- logger.trace("", this)
-}
-
fun cliCmd(logger: Logger, level: Level, lambda: suspend () -> Unit) {
// Set root log level
val root = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME) as ch.qos.logback.classic.Logger
diff --git a/common/src/main/kotlin/helpers.kt b/common/src/main/kotlin/helpers.kt
@@ -33,6 +33,7 @@ import java.util.zip.DeflaterInputStream
import java.util.zip.InflaterInputStream
import java.util.zip.ZipInputStream
import kotlin.random.Random
+import org.slf4j.Logger
/* ----- String ----- */
@@ -119,4 +120,27 @@ fun InputStream.deflate(): DeflaterInputStream
/** Inflate an input stream */
fun InputStream.inflate(): InflaterInputStream
- = InflaterInputStream(this)
-\ No newline at end of file
+ = InflaterInputStream(this)
+
+/* ----- Throwable ----- */
+
+fun Throwable.fmt(): String = buildString {
+ append(message ?: this@fmt::class.simpleName)
+ var cause = cause
+ while (cause != null) {
+ append(": ")
+ append(cause.message ?: cause::class.simpleName)
+ cause = cause.cause
+ }
+}
+
+fun Throwable.fmtLog(logger: Logger) {
+ logger.error(this.fmt())
+ logger.trace("", this)
+}
+
+/* ----- Logger ----- */
+
+inline fun Logger.debug(lambda: () -> String) {
+ if (isDebugEnabled()) debug(lambda())
+}
+\ No newline at end of file
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt
@@ -59,25 +59,7 @@ class EbicsLogger(private val dir: Path?) {
/** Create a new [order] EBICS transaction logger */
fun tx(order: EbicsOrder): TxLogger {
if (dir == null) return TxLogger(null)
- val name = buildString {
- when (order) {
- is EbicsOrder.V2_5 -> {
- append(order.type)
- append('-')
- append(order.attribute)
- }
- is EbicsOrder.V3 -> {
- append(order.type)
- for (part in sequenceOf(order.service, order.message, order.option)) {
- if (part != null) {
- append('-')
- append(part)
- }
- }
- }
- }
- }
- return tx(name)
+ return tx(order.description())
}
companion object {
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/cli/EbicsFetch.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/cli/EbicsFetch.kt
@@ -68,7 +68,7 @@ suspend fun ingestIncomingPayment(
) {
suspend fun bounce(msg: String) {
if (payment.bankId == null) {
- logger.debug("$payment ignored: missing bank ID")
+ logger.debug("{} ignored: missing bank ID", payment)
return;
}
when (accountType) {
@@ -215,7 +215,7 @@ private suspend fun fetchEbicsDocuments(
return orders.all { order ->
val doc = order.doc()
if (doc == null) {
- logger.debug("Skip unsupported order $order")
+ logger.debug("Skip unsupported order {}", order)
true
} else {
try {
@@ -272,7 +272,7 @@ class EbicsFetch: CliktCommand("Downloads and parse EBICS files from the bank an
logger.info("Transient mode: fetching once and returning.")
val pinnedStartVal = pinnedStart
val pinnedStartArg = if (pinnedStartVal != null) {
- logger.debug("Pinning start date to: $pinnedStartVal")
+ logger.debug("Pinning start date to: {}", pinnedStartVal)
dateToInstant(pinnedStartVal)
} else null
if (!fetchEbicsDocuments(client, orders, pinnedStartArg)) {
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt
@@ -29,10 +29,7 @@ import kotlinx.coroutines.withContext
import org.w3c.dom.Document
import org.xml.sax.SAXException
import tech.libeufin.common.crypto.CryptoUtil
-import tech.libeufin.common.deflate
-import tech.libeufin.common.encodeBase64
-import tech.libeufin.common.inflate
-import tech.libeufin.common.rand
+import tech.libeufin.common.*
import tech.libeufin.nexus.*
import tech.libeufin.nexus.db.Database
import java.io.InputStream
@@ -112,7 +109,19 @@ suspend fun EbicsBTS.postBTS(
} catch (e: Exception) {
throw EbicsError.Protocol("$phase: invalid ebics response", e)
}
- logger.debug("{} return codes: {} & {}", phase, response.technicalCode, response.bankCode)
+ logger.debug {
+ buildString {
+ append(phase)
+ response.content.transactionID?.let {
+ append(" for ")
+ append(it)
+ }
+ append(": ")
+ append(response.technicalCode)
+ append(" & ")
+ append(response.bankCode)
+ }
+ }
return response
}
@@ -139,6 +148,7 @@ class EbicsClient(
endDate: Instant?,
processing: suspend (InputStream) -> Unit,
) {
+ logger.debug { "Download order ${order.description()}" }
val txLog = ebicsLogger.tx(order)
val impl = EbicsBTS(cfg, bankKeys, clientKeys, order)
@@ -150,46 +160,43 @@ class EbicsClient(
impl.postBTS(client, xml, "Closing pending")
db.ebics.remove(tId)
}
-
+
// We need to run the logic in a non-cancelable context because we need to send
// a receipt for each open download transaction, otherwise we'll be stuck in an
// error loop until the pending transaction timeout.
val init = withContext(NonCancellable) {
// Init phase
val initReq = impl.downloadInitialization(startDate, endDate)
- val initResp = impl.postBTS(client, initReq, "Download init phase", txLog.step("init"))
+ val initResp = impl.postBTS(client, initReq, "Download init", txLog.step("init"))
if (initResp.bankCode == EbicsReturnCode.EBICS_NO_DOWNLOAD_DATA_AVAILABLE) {
- logger.debug("Download content is empty")
- return@withContext null
+ return@withContext null
}
- val initContent = initResp.okOrFail("Download init phase")
+ val initContent = initResp.okOrFail("Download init")
val tId = requireNotNull(initContent.transactionID) {
- "Download init phase: missing transaction ID"
+ "Download init: missing transaction ID"
}
db.ebics.register(tId)
Pair(tId, initContent)
}
val (tId, initContent) = if (init == null) return else init
val howManySegments = requireNotNull(initContent.numSegments) {
- "Download init phase: missing num segments"
+ "Download init: missing num segments"
}
val firstSegment = requireNotNull(initContent.segment) {
- "Download init phase: missing OrderData"
+ "Download init: missing OrderData"
}
val dataEncryptionInfo = requireNotNull(initContent.dataEncryptionInfo) {
- "Download init phase: missing EncryptionInfo"
+ "Download init: missing EncryptionInfo"
}
- logger.debug("Download init phase for transaction '$tId'")
-
// Transfer phase
val segments = mutableListOf(firstSegment)
for (x in 2 .. howManySegments) {
val transReq = impl.downloadTransfer(x, howManySegments, tId)
- val transResp = impl.postBTS(client, transReq, "Download transfer phase", txLog.step("transfer$x"))
- .okOrFail("Download transfer phase")
+ val transResp = impl.postBTS(client, transReq, "Download transfer", txLog.step("transfer$x"))
+ .okOrFail("Download transfer")
val segment = requireNotNull(transResp.segment) {
- "Download transfer phase: missing encrypted segment"
+ "Download transfer: missing encrypted segment"
}
segments.add(segment)
}
@@ -218,8 +225,8 @@ class EbicsClient(
// First send a proper EBICS transaction receipt
val xml = impl.downloadReceipt(tId, res.isSuccess)
- impl.postBTS(client, xml, "Download receipt phase", txLog.step("receipt"))
- .okOrFail("Download receipt phase")
+ impl.postBTS(client, xml, "Download receipt", txLog.step("receipt"))
+ .okOrFail("Download receipt")
runCatching { db.ebics.remove(tId) }
// Then throw business logic exception if any
res.getOrThrow()
@@ -236,19 +243,20 @@ class EbicsClient(
order: EbicsOrder,
payload: ByteArray,
): String {
+ logger.debug { "Upload order ${order.description()}" }
val txLog = ebicsLogger.tx(order)
val impl = EbicsBTS(cfg, bankKeys, clientKeys, order)
val preparedPayload = prepareUploadPayload(cfg, clientKeys, bankKeys, payload)
// Init phase
val initXml = impl.uploadInitialization(preparedPayload)
- val initResp = impl.postBTS(client, initXml, "Upload init phase", txLog.step("init"))
- .okOrFail("Upload init phase")
+ val initResp = impl.postBTS(client, initXml, "Upload init", txLog.step("init"))
+ .okOrFail("Upload init")
val tId = requireNotNull(initResp.transactionID) {
- "Upload init phase: missing transaction ID"
+ "Upload init: missing transaction ID"
}
val orderId = requireNotNull(initResp.orderID) {
- "Upload init phase: missing order ID"
+ "Upload init: missing order ID"
}
txLog.payload(payload, "xml")
@@ -256,8 +264,8 @@ class EbicsClient(
// Transfer phase
for (i in 1..preparedPayload.segments.size) {
val transferXml = impl.uploadTransfer(tId, preparedPayload, i)
- val transferResp = impl.postBTS(client, transferXml, "Upload transfer phase", txLog.step("transfer$i"))
- .okOrFail("Upload transfer phase")
+ val transferResp = impl.postBTS(client, transferXml, "Upload transfer", txLog.step("transfer$i"))
+ .okOrFail("Upload transfer")
}
return orderId
}
@@ -370,7 +378,7 @@ class DataEncryptionInfo(
class EbicsResponse<T>(
val technicalCode: EbicsReturnCode,
val bankCode: EbicsReturnCode,
- private val content: T
+ internal val content: T
) {
/** Checks that return codes are both EBICS_OK */
fun ok(): T? {
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsOrder.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsOrder.kt
@@ -44,6 +44,25 @@ sealed class EbicsOrder(val schema: String) {
)
}
+ fun description(): String = buildString {
+ when (this@EbicsOrder) {
+ is EbicsOrder.V2_5 -> {
+ append(type)
+ append('-')
+ append(attribute)
+ }
+ is EbicsOrder.V3 -> {
+ append(type)
+ for (part in sequenceOf(service, message, option)) {
+ if (part != null) {
+ append('-')
+ append(part)
+ }
+ }
+ }
+ }
+ }
+
fun doc(): OrderDoc? {
return when (this) {
is EbicsOrder.V2_5 -> {
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/test/TxCheck.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/test/TxCheck.kt
@@ -20,8 +20,7 @@
package tech.libeufin.nexus.test
import io.ktor.client.*
-import tech.libeufin.common.fmt
-import tech.libeufin.common.rand
+import tech.libeufin.common.*
import tech.libeufin.nexus.BankPublicKeysFile
import tech.libeufin.nexus.ClientPrivateKeysFile
import tech.libeufin.nexus.NexusEbicsConfig
@@ -89,7 +88,7 @@ suspend fun txCheck(
fetch.close(firstTxId, "Close first fetch a second time")
result.idempotentClose = true
} catch (e: Exception) {
- logger.debug(e.fmt())
+ logger.debug { e.fmt() }
}
return result
diff --git a/nexus/src/test/kotlin/EbicsTest.kt b/nexus/src/test/kotlin/EbicsTest.kt
@@ -34,14 +34,15 @@ class EbicsTest {
// code, and 200.
@Test
fun postMessage() = conf { config ->
- assertFailsWith<EbicsError.Transport> {
+ assertFailsWith<EbicsError.HTTP> {
getMockedClient {
respondError(HttpStatusCode.NotFound)
}.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
}.run {
+ assertEquals(HttpStatusCode.NotFound, status)
assertEquals("Test: bank HTTP error: 404 Not Found", message)
}
- assertFailsWith<EbicsError.Transport> {
+ assertFailsWith<EbicsError.Network> {
getMockedClient {
throw Exception("Simulate failure")
}.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
