commit ca9ab03772426ddfaa17492ad85b2667e77fb3bb
parent be8f352a7e202e0857a401f277f899ac80ebf9e3
Author: Antoine A <>
Date: Tue, 15 Jul 2025 19:16:50 +0200
nexus: log http error
Diffstat:
4 files changed, 58 insertions(+), 28 deletions(-)
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt
@@ -27,6 +27,7 @@ import java.time.*
import java.time.format.DateTimeFormatter
import kotlin.io.*
import kotlin.io.path.*
+import io.ktor.client.statement.*
/** Log EBICS transactions steps and payload if [path] is not null */
class EbicsLogger(private val dir: Path?) {
@@ -104,13 +105,39 @@ class StepLogger internal constructor(
private val dir: Path?,
private val name: String?
) {
- /** Log a protocol step [request] and [response] */
- fun log(request: ByteArray, response: InputStream): InputStream {
+ private val prefix = if (name != null) "$name-" else ""
+
+ /** Log a protocol step [request] */
+ fun logRequest(request: ByteArray) {
+ if (dir != null) {
+ dir.resolve("${prefix}request.xml")
+ .writeBytes(request, StandardOpenOption.CREATE_NEW)
+ }
+ }
+
+ /** Log a protocol step failure */
+ suspend fun logFailure(res: HttpResponse) {
+ if (dir != null) {
+ // TODO reduce allocation
+ // TODO silent io error
+ val bytes = buildString {
+ append("${res.version} ${res.status}\n")
+ for ((k, vs) in res.headers.entries()) {
+ for (v in vs) {
+ append("${k}: ${v}\n")
+ }
+ }
+ append('\n')
+ }.toByteArray() + res.readBytes()
+ dir.resolve("${prefix}failure")
+ .writeBytes(bytes, StandardOpenOption.CREATE_NEW)
+ }
+ }
+
+ /** Log a protocol step [response] */
+ fun logResponse(response: InputStream): InputStream {
if (dir == null) return response
val bytes = response.readBytes()
- val prefix = if (name != null) "$name-" else ""
- dir.resolve("${prefix}request.xml")
- .writeBytes(request, StandardOpenOption.CREATE_NEW)
dir.resolve("${prefix}response.xml")
.writeBytes(bytes, StandardOpenOption.CREATE_NEW)
return bytes.inputStream()
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt
@@ -64,8 +64,9 @@ suspend fun HttpClient.postToBank(
bankUrl: String,
msg: ByteArray,
phase: String,
- stepLogger: StepLogger? = null
+ stepLogger: StepLogger
): Document {
+ stepLogger.logRequest(msg)
val res = try {
post(urlString = bankUrl) {
contentType(ContentType.Text.Xml)
@@ -76,11 +77,12 @@ suspend fun HttpClient.postToBank(
}
if (res.status != HttpStatusCode.OK) {
+ stepLogger.logFailure(res)
throw EbicsError.HTTP("$phase: bank HTTP error: ${res.status}", res.status)
}
try {
val bodyStream = res.bodyAsChannel().toInputStream()
- val loggedStream = stepLogger?.log(msg, bodyStream) ?: bodyStream
+ val loggedStream = stepLogger.logResponse(bodyStream)
return XMLUtil.parseIntoDom(loggedStream)
} catch (e: SAXException) {
throw EbicsError.Protocol("$phase: invalid XML bank response", e)
@@ -94,7 +96,7 @@ suspend fun EbicsBTS.postBTS(
client: HttpClient,
xmlReq: ByteArray,
phase: String,
- stepLogger: StepLogger? = null
+ stepLogger: StepLogger
): BTSResponse {
val doc = client.postToBank(cfg.host.baseUrl, xmlReq, phase, stepLogger)
try {
@@ -165,16 +167,16 @@ class EbicsClient(
}
}
}
- val txLog = ebicsLogger.tx(order)
val impl = EbicsBTS(cfg.ebics, bankKeys, clientKeys, order)
// Close interrupted
+ val interruptedLog = ebicsLogger.tx("INTD")
while (true) {
val tId = db.ebics.first()
if (tId == null) break
val xml = impl.downloadReceipt(tId, false)
try {
- impl.postBTS(client, xml, "Closing interrupted transaction ${tId}")
+ impl.postBTS(client, xml, "Closing interrupted transaction ${tId}", interruptedLog.step(tId))
} catch (e: Exception) {
when (e) {
// Transaction already closed or expired - EBICS protocol error
@@ -189,6 +191,8 @@ class EbicsClient(
db.ebics.remove(tId)
}
+ val txLog = ebicsLogger.tx(order)
+
// 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.
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/test/TxCheck.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/test/TxCheck.kt
@@ -21,11 +21,8 @@ package tech.libeufin.nexus.test
import io.ktor.client.*
import tech.libeufin.common.*
-import tech.libeufin.nexus.BankPublicKeysFile
-import tech.libeufin.nexus.ClientPrivateKeysFile
-import tech.libeufin.nexus.NexusEbicsConfig
import tech.libeufin.nexus.ebics.*
-import tech.libeufin.nexus.logger
+import tech.libeufin.nexus.*
data class TxCheckResult(
var concurrentFetchAndFetch: Boolean = false,
@@ -52,37 +49,38 @@ suspend fun txCheck(
val result = TxCheckResult()
val fetch = EbicsBTS(cfg, bankKeys, clientKeys, fetchOrder)
val submit = EbicsBTS(cfg, bankKeys, clientKeys, submitOrder)
+ val ebicsLogger = EbicsLogger(null).tx("test").step("step")
- suspend fun EbicsBTS.close(id: String, phase: String) {
+ suspend fun EbicsBTS.close(id: String, phase: String, ebicsLogger: StepLogger) {
val xml = downloadReceipt(id, false)
- postBTS(client, xml, phase)
+ postBTS(client, xml, phase, ebicsLogger)
}
- val firstTxId = fetch.postBTS(client, fetch.downloadInitialization(null, null), "Init first fetch")
+ val firstTxId = fetch.postBTS(client, fetch.downloadInitialization(null, null), "Init first fetch", ebicsLogger)
.transactionID!!
try {
try {
- val id = fetch.postBTS(client, fetch.downloadInitialization(null, null), "Init second fetch").transactionID!!
+ val id = fetch.postBTS(client, fetch.downloadInitialization(null, null), "Init second fetch", ebicsLogger).transactionID!!
result.concurrentFetchAndFetch = true
- fetch.close(id, "Init second fetch")
+ fetch.close(id, "Init second fetch", ebicsLogger)
} catch (e: EbicsError.Code) {}
var paylod = prepareUploadPayload(cfg, clientKeys, bankKeys, ByteArray(2000000).rand())
try {
- val submitId = submit.postBTS(client, submit.uploadInitialization(paylod), "Init first submit"). transactionID!!
+ val submitId = submit.postBTS(client, submit.uploadInitialization(paylod), "Init first submit", ebicsLogger). transactionID!!
result.concurrentFetchAndSubmit = true
- submit.postBTS(client, submit.uploadTransfer(submitId, paylod, 1), "Submit first upload")
+ submit.postBTS(client, submit.uploadTransfer(submitId, paylod, 1), "Submit first upload", ebicsLogger)
try {
- submit.postBTS(client, submit.uploadInitialization(paylod), "Init second submit")
+ submit.postBTS(client, submit.uploadInitialization(paylod), "Init second submit", ebicsLogger)
result.concurrentSubmitAndSubmit = true
} catch (e: EbicsError.Code) {}
} catch (e: EbicsError.Code) {}
} finally {
- fetch.close(firstTxId, "Close first fetch")
+ fetch.close(firstTxId, "Close first fetch", ebicsLogger)
}
try {
- fetch.close(firstTxId, "Close first fetch a second time")
+ fetch.close(firstTxId, "Close first fetch a second time", ebicsLogger)
result.idempotentClose = true
} catch (e: Exception) {
logger.debug { e.fmt() }
diff --git a/nexus/src/test/kotlin/EbicsTest.kt b/nexus/src/test/kotlin/EbicsTest.kt
@@ -403,6 +403,7 @@ class EbicsTest {
private val nexusCmd = LibeufinNexus()
private val bank = EbicsState()
private val args = "-L TRACE -c conf/fetch.conf"
+ private val ebicsLogger = EbicsLogger(null).tx("test").step("step")
private fun setMock(sequences: Sequence<(String) -> ByteArray>) {
val steps = sequences.iterator()
@@ -448,7 +449,7 @@ class EbicsTest {
assertFailsWith<EbicsError.HTTP> {
getMockedClient {
respondError(HttpStatusCode.NotFound)
- }.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
+ }.postToBank("http://ignored.example.com/", ByteArray(0), "Test", ebicsLogger)
}.run {
assertEquals(HttpStatusCode.NotFound, status)
assertEquals("Test: bank HTTP error: 404 Not Found", message)
@@ -456,7 +457,7 @@ class EbicsTest {
assertFailsWith<EbicsError.Network> {
getMockedClient {
throw Exception("Simulate failure")
- }.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
+ }.postToBank("http://ignored.example.com/", ByteArray(0), "Test", ebicsLogger)
}.run {
assertEquals("Test: failed to contact bank", message)
assertEquals("Simulate failure", cause!!.message)
@@ -464,14 +465,14 @@ class EbicsTest {
assertFailsWith<EbicsError.Protocol> {
getMockedClient {
respondOk("<ebics broken></ebics>")
- }.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
+ }.postToBank("http://ignored.example.com/", ByteArray(0), "Test", ebicsLogger)
}.run {
assertEquals("Test: invalid XML bank response", message)
assertEquals("Attribute name \"broken\" associated with an element type \"ebics\" must be followed by the ' = ' character.", cause!!.message)
}
getMockedClient {
respondOk("<ebics></ebics>")
- }.postToBank("http://ignored.example.com/", ByteArray(0), "Test")
+ }.postToBank("http://ignored.example.com/", ByteArray(0), "Test", ebicsLogger)
}
// Tests that internal repr. of keys lead to valid PDF.
