From 7d8d4d18848aa209bfe62c430faab469910c92d1 Mon Sep 17 00:00:00 2001 From: Florian Roks Date: Thu, 10 Feb 2022 14:50:24 +0100 Subject: [PATCH] add logging level for requestmatchers --- src/main/kotlin/SimDsl.kt | 34 ++++++++++++++++----- src/main/kotlin/SimEcu.kt | 30 +++++++++++------- src/main/kotlin/library/LoggerExtensions.kt | 7 +++++ src/main/kotlin/library/SimulatedEcu.kt | 4 +-- src/main/resources/logback.xml | 2 +- 5 files changed, 56 insertions(+), 21 deletions(-) diff --git a/src/main/kotlin/SimDsl.kt b/src/main/kotlin/SimDsl.kt index b06adaf..d7285f0 100644 --- a/src/main/kotlin/SimDsl.kt +++ b/src/main/kotlin/SimDsl.kt @@ -196,6 +196,7 @@ class RequestMatcher( val name: String?, val requestBytes: ByteArray?, val requestRegex: Regex?, + val loglevel: LogLevel = LogLevel.DEBUG, val responseHandler: RequestResponseHandler ) : DataStorage() { init { @@ -242,6 +243,13 @@ fun MutableList.removeByName(name: String): RequestMatcher? { data class ResetHandler(val name: String?, val handler: (SimEcu) -> Unit) +enum class LogLevel { + ERROR, + INFO, + DEBUG, + TRACE, +} + open class RequestsData( val name: String, /** @@ -284,8 +292,14 @@ open class RequestsData( * Define request-matcher & response-handler for a gateway or ecu by using an * exact matching byte-array */ - fun request(request: ByteArray, name: String? = null, response: RequestResponseHandler = {}): RequestMatcher { - val req = RequestMatcher(name = name, requestBytes = request, requestRegex = null, responseHandler = response) + fun request(request: ByteArray, name: String? = null, loglevel: LogLevel = LogLevel.DEBUG, response: RequestResponseHandler = {}): RequestMatcher { + val req = RequestMatcher( + name = name, + requestBytes = request, + requestRegex = null, + loglevel = loglevel, + responseHandler = response + ) requests.add(req) return req } @@ -300,8 +314,14 @@ open class RequestsData( * Note: Take the maximal string length [requestRegexMatchBytes] into * account */ - fun request(reqRegex: Regex, name: String? = null, response: RequestResponseHandler = {}): RequestMatcher { - val req = RequestMatcher(name = name, requestBytes = null, requestRegex = reqRegex, responseHandler = response) + fun request(reqRegex: Regex, name: String? = null, loglevel: LogLevel = LogLevel.DEBUG, response: RequestResponseHandler = {}): RequestMatcher { + val req = RequestMatcher( + name = name, + requestBytes = null, + requestRegex = reqRegex, + loglevel = loglevel, + responseHandler = response + ) requests.add(req) return req } @@ -317,11 +337,11 @@ open class RequestsData( * is automatically converted into a regular expression by replacing all "[]" with ".*", * turning it into uppercase, and removing all spaces. */ - fun request(reqHex: String, name: String? = null, response: RequestResponseHandler = {}) { + fun request(reqHex: String, name: String? = null, loglevel: LogLevel = LogLevel.DEBUG, response: RequestResponseHandler = {}) { if (isRegex(reqHex)) { - request(regexifyRequestHex(reqHex), name, response) + request(regexifyRequestHex(reqHex), name, loglevel, response) } else { - request(reqHex.decodeHex(), name, response) + request(reqHex.decodeHex(), name, loglevel, response) } } diff --git a/src/main/kotlin/SimEcu.kt b/src/main/kotlin/SimEcu.kt index cef7d55..d2ea06a 100644 --- a/src/main/kotlin/SimEcu.kt +++ b/src/main/kotlin/SimEcu.kt @@ -80,7 +80,7 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { return false } - override fun handleRequestIfBusy(request: UdsMessage){ + override fun handleRequestIfBusy(request: UdsMessage) { if (handleInterceptors(request, true)) { logger.debugIf { "[${name}] Incoming busy request ${request.message.toHexString(limit = 10)} was handled by interceptors" } } @@ -110,11 +110,11 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { requestIter.requestRegex!!.matches(normalizedRequest) } } catch (e: Exception) { - logger.error("[${name}] Error while matching requests: ${e.message}") + logger.error("Error while matching requests for $name: ${e.message}", e) throw e } - logger.traceIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' try match '$requestIter' -> $matches" } + logger.traceIf { "Request for $name: '${request.message.toHexString(limit = 10)}' try match '$requestIter' -> $matches" } if (!matches) { continue @@ -123,22 +123,22 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { val responseData = ResponseData(caller = requestIter, request = request, ecu = this) requestIter.responseHandler.invoke(responseData) if (responseData.continueMatching) { - logger.debugIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> Continue matching" } + logger.logForRequest(requestIter) { "Request for $name: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> Continue matching" } continue } else if (responseData.response.isNotEmpty()) { - logger.debugIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> Send response '${responseData.response.toHexString(limit = 10)}'" } + logger.logForRequest(requestIter) { "Request for $name: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> Send response '${responseData.response.toHexString(limit = 10)}'" } sendResponse(request, responseData.response) } else { - logger.debugIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> No response" } + logger.logForRequest(requestIter) { "Request for $name: '${request.message.toHexString(limit = 10)}' matched '$requestIter' -> No response" } } return } if (this.data.nrcOnNoMatch) { - logger.debugIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' no matching request found -> Sending NRC" } + logger.debugIf { "Request for $name: '${request.message.toHexString(limit = 10)}' no matching request found -> Sending NRC" } sendResponse(request, byteArrayOf(0x7F, request.message[0], NrcError.RequestOutOfRange)) } else { - logger.debugIf { "[${name}] Request: '${request.message.toHexString(limit = 10)}' no matching request found -> Ignore (nrcOnNoMatch = false)" } + logger.debugIf { "Request for $name: '${request.message.toHexString(limit = 10)}' no matching request found -> Ignore (nrcOnNoMatch = false)" } } } @@ -153,7 +153,7 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { alsoCallWhenEcuIsBusy: Boolean = false, interceptor: InterceptorResponseHandler ): String { - logger.traceIf { "[${this.name}] Adding interceptor '$name' for $duration (busy: $alsoCallWhenEcuIsBusy)"} + logger.traceIf { "Adding interceptor '$name' for $duration (busy: $alsoCallWhenEcuIsBusy) in ecu $name"} // expires at expirationTime val expirationTime = if (duration == Duration.INFINITE) Long.MAX_VALUE else System.nanoTime() + duration.inWholeNanoseconds @@ -180,7 +180,7 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { * Please note that the internal resolution for delay is milliseconds */ fun addOrReplaceTimer(name: String, delay: Duration, handler: TimerTask.() -> Unit) { - logger.traceIf { "[${this.name}] Adding or replacing timer '$name' to be executed after $delay"} + logger.traceIf { "Adding or replacing timer '$name' for $name to be executed after $delay"} synchronized(mainTimer) { timers[name]?.cancel() @@ -201,7 +201,7 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { * Explicitly cancel a running timer */ fun cancelTimer(name: String) { - logger.traceIf { "[${this.name}] Cancelling timer '$name'" } + logger.traceIf { "Cancelling timer '$name' for $name" } synchronized(mainTimer) { timers[name]?.cancel() timers.remove(name) @@ -241,3 +241,11 @@ class SimEcu(private val data: EcuData) : SimulatedEcu(data.toEcuConfig()) { } } } + +fun Logger.logForRequest(request: RequestMatcher, t: Throwable? = null, supplier: () -> String) = + when (request.loglevel) { + LogLevel.ERROR -> this.errorIf(t, supplier) + LogLevel.INFO -> this.infoIf(t, supplier) + LogLevel.DEBUG -> this.debugIf(t, supplier) + LogLevel.TRACE -> this.traceIf(t, supplier) + } diff --git a/src/main/kotlin/library/LoggerExtensions.kt b/src/main/kotlin/library/LoggerExtensions.kt index d9ffbe6..6c73f58 100644 --- a/src/main/kotlin/library/LoggerExtensions.kt +++ b/src/main/kotlin/library/LoggerExtensions.kt @@ -19,3 +19,10 @@ fun Logger.infoIf(t: Throwable? = null, supplier: () -> String) { this.info(supplier.invoke(), t) } } + +fun Logger.errorIf(t: Throwable? = null, supplier: () -> String) { + if (this.isErrorEnabled) { + this.error(supplier.invoke(), t) + } +} + diff --git a/src/main/kotlin/library/SimulatedEcu.kt b/src/main/kotlin/library/SimulatedEcu.kt index 1ddf1a4..fd3225a 100644 --- a/src/main/kotlin/library/SimulatedEcu.kt +++ b/src/main/kotlin/library/SimulatedEcu.kt @@ -13,12 +13,12 @@ open class SimulatedEcu(val config: EcuConfig) { private val isBusy: AtomicBoolean = AtomicBoolean(false) open fun handleRequest(request: UdsMessage) { - logger.debugIf { "[${name}] Handle Request message: ${request.message.toHexString(limit = 20)}" } + logger.debugIf { "Handle Request message: ${request.message.toHexString(limit = 20)} for $name" } } open fun handleRequestIfBusy(request: UdsMessage) { // Busy NRC - logger.debugIf { "[${name}] ECU is busy, sending busy-NRC" } + logger.debugIf { "ECU $name is busy, sending busy-NRC" } request.respond(byteArrayOf(0x7f, request.message[0], 0x21)) } diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml index 26a6d8e..ef436ca 100644 --- a/src/main/resources/logback.xml +++ b/src/main/resources/logback.xml @@ -3,7 +3,7 @@ - %cyan(%d{HH:mm:ss.SSS}) %highlight(%-5level) %green([%thread]) %magenta(%logger{12}) %boldWhite(%mdc{ecu:-NONE}) %msg%n + %cyan(%d{HH:mm:ss.SSS}) %highlight(%-5level) %green([%thread]) %magenta(%logger{12}) %boldWhite([%mdc{ecu:-NONE}]) %msg%n