commit fb48008197b479358a2344c4d4d99c1adac53f87
parent 73db3cc180f42335bccfa114c1dbc71ee477fd16
Author: Antoine A <>
Date: Thu, 11 Jul 2024 15:31:34 +0200
nexus: log every EBICS steps
Diffstat:
8 files changed, 205 insertions(+), 131 deletions(-)
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsFetch.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsFetch.kt
@@ -229,11 +229,7 @@ private suspend fun fetchEbicsDocuments(
lastExecutionTime,
null
) { payload ->
- val loggedPayload = client.fileLogger.logFetch(
- payload,
- doc == SupportedDocument.PAIN_002_LOGS
- )
- ingestPayload(client.db, client.cfg, loggedPayload, doc)
+ ingestPayload(client.db, client.cfg, payload, doc)
}
true
} catch (e: Exception) {
@@ -315,7 +311,7 @@ class EbicsFetch: CliktCommand("Fetches EBICS files") {
cfg,
httpClient(),
db,
- FileLogger(ebicsLog),
+ EbicsLogger(ebicsLog),
clientKeys,
bankKeys
)
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsLogger.kt
@@ -0,0 +1,137 @@
+/*
+ * This file is part of LibEuFin.
+ * Copyright (C) 2024 Taler Systems S.A.
+
+ * LibEuFin is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation; either version 3, or
+ * (at your option) any later version.
+
+ * LibEuFin is distributed in the hope that it will be useful, but
+ * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
+ * or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Affero General
+ * Public License for more details.
+
+ * You should have received a copy of the GNU Affero General Public
+ * License along with LibEuFin; see the file COPYING. If not, see
+ * <http://www.gnu.org/licenses/>
+ */
+
+package tech.libeufin.nexus
+
+import tech.libeufin.nexus.ebics.EbicsOrder
+import tech.libeufin.common.*
+import java.io.*
+import java.nio.file.*
+import java.time.*
+import java.time.format.DateTimeFormatter
+import kotlin.io.*
+import kotlin.io.path.*
+
+/** Log EBICS transactions steps and payload if [path] is not null */
+class EbicsLogger(path: String?) {
+ private val dir = if (path != null) Path(path) else null
+
+ init {
+ if (dir != null) {
+ try {
+ // Create logging directory if missing
+ dir.createDirectories()
+ } catch (e: Exception) {
+ throw Exception("Failed to init EBICS debug logging directory", e)
+ }
+ logger.info("Logging to '$dir'")
+ }
+ }
+
+ /** Create a new [name] EBICS transaction logger */
+ fun tx(name: String): TxLogger {
+ if (dir == null) return TxLogger(null)
+ val utcDateTime = Instant.now().atOffset(ZoneOffset.UTC)
+ val txDir = dir
+ // yyyy-MM-dd per day directory
+ .resolve(utcDateTime.format(DateTimeFormatter.ISO_LOCAL_DATE))
+ // HH:mm:ss.SSS-name per transaction directory
+ .resolve("${utcDateTime.format(TIME_WITH_MS)}-$name")
+ txDir.createDirectories()
+ return TxLogger(txDir)
+ }
+
+ /** 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.name, order.messageName, order.option)) {
+ if (part != null) {
+ append('-')
+ append(part)
+ }
+ }
+ }
+ }
+ }
+ return tx(name)
+ }
+
+ companion object {
+ private val TIME_WITH_MS = DateTimeFormatter.ofPattern("HH:mm:ss.SSS");
+ }
+}
+
+/** Log EBICS transaction steps and payload */
+class TxLogger internal constructor(
+ private val dir: Path?
+) {
+ /** Create a new [name] EBICS transaction step logger*/
+ fun step(name: String? = null) = StepLogger(dir, name)
+
+ /** Log a [stream] EBICS transaction payload of [type] */
+ fun payload(stream: InputStream, type: String = "xml"): InputStream {
+ if (dir == null) return stream
+ return payload(stream.readBytes(), type).inputStream()
+ }
+
+ /** Log a [content] EBICS transaction payload of [type] */
+ fun payload(content: ByteArray, type: String = "xml"): ByteArray {
+ if (dir == null) return content
+ val type = type.lowercase()
+ if (type == "zip") {
+ val payloadDir = dir.resolve("payload")
+ payloadDir.createDirectory()
+ content.inputStream().unzipEach { fileName, xmlContent ->
+ xmlContent.use {
+ Files.copy(it, payloadDir.resolve(fileName))
+ }
+ }
+ } else {
+ dir.resolve("payload.$type").writeBytes(content, StandardOpenOption.CREATE_NEW)
+ }
+ return content
+ }
+}
+
+/** Log EBICS transaction protocol step */
+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 {
+ 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()
+ }
+}
+\ No newline at end of file
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsSetup.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsSetup.kt
@@ -68,12 +68,10 @@ suspend fun doKeysRequestAndUpdateState(
cfg: NexusConfig,
privs: ClientPrivateKeysFile,
client: HttpClient,
+ ebicsLogger: EbicsLogger,
order: EbicsKeyMng.Order
) {
- logger.info("Doing key request $order")
- val req = EbicsKeyMng(cfg, privs, true).request(order)
- val xml = client.postToBank(cfg.hostBaseUrl, req, order.name)
- val resp = EbicsKeyMng.parseResponse(xml, privs.encryption_private_key)
+ val resp = keyManagement(cfg, privs, client, ebicsLogger, order)
when (order) {
INI, HIA -> {
@@ -161,13 +159,15 @@ class EbicsSetup: CliktCommand("Set up the EBICS subscriber") {
*/
override fun run() = cliCmd(logger, common.log) {
val cfg = nexusConfig(common.config)
+
val client = httpClient()
+ val ebicsLogger = EbicsLogger(ebicsLog)
val clientKeys = loadOrGenerateClientKeys(cfg.clientPrivateKeysPath)
var bankKeys = loadBankKeys(cfg.bankPublicKeysPath)
// Check EBICS 3 support
- val versions = HEV(client, cfg)
+ val versions = HEV(client, cfg, ebicsLogger)
logger.debug("HEV: {}", versions)
if (!versions.contains(VersionNumber(3.0f, "H005")) && !versions.contains(VersionNumber(3.02f, "H005"))) {
throw Exception("EBICS 3 is not supported by your bank")
@@ -176,15 +176,15 @@ class EbicsSetup: CliktCommand("Set up the EBICS subscriber") {
// Privs exist. Upload their pubs
val keysNotSub = !clientKeys.submitted_ini
if ((!clientKeys.submitted_ini) || forceKeysResubmission)
- doKeysRequestAndUpdateState(cfg, clientKeys, client, INI)
+ doKeysRequestAndUpdateState(cfg, clientKeys, client, ebicsLogger, INI)
// Eject PDF if the keys were submitted for the first time, or the user asked.
if (keysNotSub || generateRegistrationPdf) makePdf(clientKeys, cfg)
if ((!clientKeys.submitted_hia) || forceKeysResubmission)
- doKeysRequestAndUpdateState(cfg, clientKeys, client, HIA)
+ doKeysRequestAndUpdateState(cfg, clientKeys, client, ebicsLogger, HIA)
// Checking if the bank keys exist on disk
if (bankKeys == null) {
- doKeysRequestAndUpdateState(cfg, clientKeys, client, HPB)
+ doKeysRequestAndUpdateState(cfg, clientKeys, client, ebicsLogger, HPB)
logger.info("Bank keys stored at ${cfg.bankPublicKeysPath}")
bankKeys = loadBankKeys(cfg.bankPublicKeysPath)!!
}
@@ -212,7 +212,7 @@ class EbicsSetup: CliktCommand("Set up the EBICS subscriber") {
cfg,
client,
db,
- FileLogger(ebicsLog),
+ ebicsLogger,
clientKeys,
bankKeys
).download(EbicsOrder.V3("HKD"), null, null) { stream ->
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsSubmit.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/EbicsSubmit.kt
@@ -62,7 +62,6 @@ private suspend fun submitInitiatedPayment(
wireTransferSubject = payment.wireTransferSubject,
dialect = client.cfg.dialect
)
- client.fileLogger.logSubmit(xml)
return client.upload(
client.cfg.dialect.directDebit(),
xml
@@ -112,7 +111,7 @@ class EbicsSubmit : CliktCommand("Submits any initiated payment found in the dat
cfg,
httpClient(),
db,
- FileLogger(ebicsLog),
+ EbicsLogger(ebicsLog),
clientKeys,
bankKeys
)
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/Log.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/Log.kt
@@ -1,95 +0,0 @@
-/*
- * This file is part of LibEuFin.
- * Copyright (C) 2024 Taler Systems S.A.
-
- * LibEuFin is free software; you can redistribute it and/or modify
- * it under the terms of the GNU Affero General Public License as
- * published by the Free Software Foundation; either version 3, or
- * (at your option) any later version.
-
- * LibEuFin is distributed in the hope that it will be useful, but
- * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
- * or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Affero General
- * Public License for more details.
-
- * You should have received a copy of the GNU Affero General Public
- * License along with LibEuFin; see the file COPYING. If not, see
- * <http://www.gnu.org/licenses/>
- */
-
-package tech.libeufin.nexus
-
-import tech.libeufin.common.*
-import java.io.*
-import java.nio.file.*
-import java.time.*
-import kotlin.io.*
-import kotlin.io.path.*
-
-/**
- * Log EBICS files for debugging
- *
- * Only log if [path] is not null
- */
-class FileLogger(path: String?) {
- private val dir = if (path != null) Path(path) else null
-
- init {
- if (dir != null) {
- try {
- // Create logging directory if missing
- dir.createDirectories()
- } catch (e: Exception) {
- throw Exception("Failed to init EBICS debug logging directory", e)
- }
- logger.info("Logging to '$dir'")
- }
- }
-
- /**
- * Logs EBICS fetch content if EBICS debug logging is enabled
- *
- * @param stream EBICS fetch content
- * @param hac only true when downloading via HAC (EBICS 2)
- */
- fun logFetch(stream: InputStream, hac: Boolean = false): InputStream {
- if (dir == null) return stream
- val content = stream.readBytes()
- // Subdir based on current day.
- val now = Instant.now()
- val asUtcDate = LocalDate.ofInstant(now, ZoneId.of("UTC"))
- val nowMs = now.micros()
- // Creating the combined dir.
- val subDir = dir.resolve("${asUtcDate.year}-${asUtcDate.monthValue}-${asUtcDate.dayOfMonth}").resolve("fetch")
- subDir.createDirectories()
- if (hac) {
- subDir.resolve("${nowMs}_HAC_response.pain.002.xml").writeBytes(content)
- } else {
- // Write each ZIP entry in the combined dir.
- content.inputStream().unzipEach { fileName, xmlContent ->
- xmlContent.use {
- Files.copy(it, subDir.resolve("${nowMs}_$fileName"))
- }
- }
- }
- return content.inputStream()
- }
-
- /**
- * Logs EBICS submit content if EBICS debug logging is enabled
- *
- * @param content EBICS submit content
- */
- fun logSubmit(content: ByteArray) {
- if (dir == null) return
-
- // Subdir based on current day.
- val now = Instant.now()
- val asUtcDate = LocalDate.ofInstant(now, ZoneId.of("UTC"))
- val nowMs = now.micros()
- // Creating the combined dir.
- val subDir = dir.resolve("${asUtcDate.year}-${asUtcDate.monthValue}-${asUtcDate.dayOfMonth}").resolve("submit")
- subDir.createDirectories()
- subDir.resolve("${nowMs}_pain.001.xml").writeBytes(content)
- }
-}
-\ No newline at end of file
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/Main.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/Main.kt
@@ -250,7 +250,7 @@ class EbicsDownload: CliktCommand("Perform EBICS requests", name = "ebics-btd")
cfg,
httpClient(),
db,
- FileLogger(ebicsLog),
+ EbicsLogger(ebicsLog),
clientKeys,
bankKeys
)
@@ -261,13 +261,11 @@ class EbicsDownload: CliktCommand("Perform EBICS requests", name = "ebics-btd")
null
) { stream ->
if (container == "ZIP") {
- val stream = client.fileLogger.logFetch(stream, false)
stream.unzipEach { fileName, xmlContent ->
println(fileName)
println(xmlContent.readBytes().toString(Charsets.UTF_8))
}
} else {
- val stream = client.fileLogger.logFetch(stream, true) // TODO better name
println(stream.readBytes().toString(Charsets.UTF_8))
}
if (dryRun) throw DryRun()
diff --git a/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt b/nexus/src/main/kotlin/tech/libeufin/nexus/ebics/EbicsCommon.kt
@@ -57,7 +57,12 @@ sealed class EbicsError(msg: String, cause: Throwable? = null): Exception(msg, c
}
/** POST an EBICS request [msg] to [bankUrl] returning a parsed XML response */
-suspend fun HttpClient.postToBank(bankUrl: String, msg: ByteArray, phase: String): Document {
+suspend fun HttpClient.postToBank(
+ bankUrl: String,
+ msg: ByteArray,
+ phase: String,
+ stepLogger: StepLogger? = null
+): Document {
val res = try {
post(urlString = bankUrl) {
contentType(ContentType.Text.Xml)
@@ -71,7 +76,9 @@ suspend fun HttpClient.postToBank(bankUrl: String, msg: ByteArray, phase: String
throw EbicsError.Transport("$phase: bank HTTP error: ${res.status}")
}
try {
- return XMLUtil.parseIntoDom(res.bodyAsChannel().toInputStream())
+ val bodyStream = res.bodyAsChannel().toInputStream();
+ val loggedStream = stepLogger?.log(msg, bodyStream) ?: bodyStream
+ return XMLUtil.parseIntoDom(loggedStream)
} catch (e: SAXException) {
throw EbicsError.Protocol("$phase: invalid XML bank response", e)
} catch (e: Exception) {
@@ -84,8 +91,9 @@ suspend fun EbicsBTS.postBTS(
client: HttpClient,
xmlReq: ByteArray,
phase: String,
+ stepLogger: StepLogger? = null
): EbicsResponse<BTSResponse> {
- val doc = client.postToBank(cfg.hostBaseUrl, xmlReq, phase)
+ val doc = client.postToBank(cfg.hostBaseUrl, xmlReq, phase, stepLogger)
if (!XMLUtil.verifyEbicsDocument(
doc,
bankKeys.bank_authentication_public_key
@@ -106,7 +114,7 @@ class EbicsClient(
val cfg: NexusConfig,
val client: HttpClient,
val db: Database,
- val fileLogger: FileLogger,
+ val ebicsLogger: EbicsLogger,
val clientKeys: ClientPrivateKeysFile,
val bankKeys: BankPublicKeysFile
) {
@@ -124,6 +132,7 @@ class EbicsClient(
endDate: Instant?,
processing: suspend (InputStream) -> Unit,
) {
+ val txLog = ebicsLogger.tx(order)
val impl = EbicsBTS(cfg, bankKeys, clientKeys, order)
// Close pending
@@ -141,7 +150,7 @@ class EbicsClient(
val init = withContext(NonCancellable) {
// Init phase
val initReq = impl.downloadInitialization(startDate, endDate)
- val initResp = impl.postBTS(client, initReq, "Download init phase")
+ val initResp = impl.postBTS(client, initReq, "Download init phase", txLog.step("init"))
if (initResp.bankCode == EbicsReturnCode.EBICS_NO_DOWNLOAD_DATA_AVAILABLE) {
logger.debug("Download content is empty")
return@withContext null
@@ -170,7 +179,8 @@ class EbicsClient(
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").okOrFail("Download transfer phase")
+ val transResp = impl.postBTS(client, transReq, "Download transfer phase", txLog.step("transfer$x"))
+ .okOrFail("Download transfer phase")
val segment = requireNotNull(transResp.segment) {
"Download transfer phase: missing encrypted segment"
}
@@ -188,14 +198,21 @@ class EbicsClient(
throw EbicsError.Protocol("invalid chunks", e)
}
+ val container = when (order) {
+ is EbicsOrder.V2_5 -> "rax" // TODO infer ?
+ is EbicsOrder.V3 -> order.container ?: "xml"
+ }
+ val loggedStream = txLog.payload(payloadStream, container)
+
// Run business logic
val res = runCatching {
- processing(payloadStream)
+ processing(loggedStream)
}
// First send a proper EBICS transaction receipt
val xml = impl.downloadReceipt(tId, res.isSuccess)
- impl.postBTS(client, xml, "Download receipt phase").okOrFail("Download receipt phase")
+ impl.postBTS(client, xml, "Download receipt phase", txLog.step("receipt"))
+ .okOrFail("Download receipt phase")
runCatching { db.ebics.remove(tId) }
// Then throw business logic exception if any
res.getOrThrow()
@@ -212,12 +229,14 @@ class EbicsClient(
order: EbicsOrder,
payload: ByteArray,
): String {
+ 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").okOrFail("Upload init phase")
+ val initResp = impl.postBTS(client, initXml, "Upload init phase", txLog.step("init"))
+ .okOrFail("Upload init phase")
val tId = requireNotNull(initResp.transactionID) {
"Upload init phase: missing transaction ID"
}
@@ -225,10 +244,13 @@ class EbicsClient(
"Upload init phase: missing order ID"
}
+ txLog.payload(payload, "xml")
+
// 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").okOrFail("Upload transfer phase")
+ val transferResp = impl.postBTS(client, transferXml, "Upload transfer phase", txLog.step("transfer$i"))
+ .okOrFail("Upload transfer phase")
}
return orderId
}
@@ -236,14 +258,30 @@ class EbicsClient(
suspend fun HEV(
client: HttpClient,
- cfg: NexusConfig
+ cfg: NexusConfig,
+ ebicsLogger: EbicsLogger
): List<VersionNumber> {
logger.info("Doing administrative request HEV")
+ val txLog = ebicsLogger.tx("HEV")
val req = EbicsAdministrative.HEV(cfg)
- val xml = client.postToBank(cfg.hostBaseUrl, req, "HEV")
+ val xml = client.postToBank(cfg.hostBaseUrl, req, "HEV", txLog.step())
return EbicsAdministrative.parseHEV(xml).okOrFail("HEV")
}
+suspend fun keyManagement(
+ cfg: NexusConfig,
+ privs: ClientPrivateKeysFile,
+ client: HttpClient,
+ ebicsLogger: EbicsLogger,
+ order: EbicsKeyMng.Order
+): EbicsResponse<InputStream?> {
+ logger.info("Doing key request $order")
+ val txLog = ebicsLogger.tx(order.name)
+ val req = EbicsKeyMng(cfg, privs, true).request(order)
+ val xml = client.postToBank(cfg.hostBaseUrl, req, order.name, txLog.step())
+ return EbicsKeyMng.parseResponse(xml, privs.encryption_private_key)
+}
+
class PreparedUploadData(
val transactionKey: ByteArray,
val userSignatureDataEncrypted: String,
diff --git a/testbench/src/main/kotlin/Main.kt b/testbench/src/main/kotlin/Main.kt
@@ -118,7 +118,8 @@ class Cli : CliktCommand("Run integration tests on banks provider") {
// Prepare cmds
val log = "DEBUG"
val flags = " -c $conf -L $log"
- val ebicsFlags = "$flags --transient --debug-ebics test/$platform"
+ val debugFlags = "$flags --debug-ebics test/$platform"
+ val ebicsFlags = "$debugFlags --transient"
val clientKeysPath = cfg.clientPrivateKeysPath
val bankKeysPath = cfg.bankPublicKeysPath
val currency = cfg.currency
@@ -164,7 +165,7 @@ class Cli : CliktCommand("Run integration tests on banks provider") {
put("list-outgoing", "List outgoing transaction", "testing list $flags outgoing")
put("list-initiated", "List initiated payments", "testing list $flags initiated")
put("submit", "Submit pending transactions", "ebics-submit $ebicsFlags")
- put("setup", "Setup", "ebics-setup $flags")
+ put("setup", "Setup", "ebics-setup $debugFlags")
put("reset-keys", suspend {
if (kind.test) {
clientKeysPath.deleteIfExists()
@@ -218,7 +219,7 @@ class Cli : CliktCommand("Run integration tests on banks provider") {
throw Exception("Clients keys are required to run netzbon tests")
} else if (clientKeys == null || !clientKeys.submitted_ini || !clientKeys.submitted_hia || bankKeys == null || !bankKeys.accepted) {
step("Run EBICS setup")
- if (!nexusCmd.run("ebics-setup --auto-accept-keys $flags")) {
+ if (!nexusCmd.run("ebics-setup --auto-accept-keys $debugFlags")) {
clientKeys = loadClientKeys(clientKeysPath)
if (kind.test) {
if (clientKeys == null || !clientKeys.submitted_ini || !clientKeys.submitted_hia) {
