Log API queries at DEBUG level - #2456
Conversation
Log method, relative URI, response status and elapsed time for every query served by the node's HTTP interface. Bodies are not logged: requests to this API carry secrets (mnemonic on /wallet/restore, password on /wallet/unlock). Logging goes through ScorexLogging rather than akka's LoggingAdapter, so no dependency is added and the node's HTTP verbosity is not tied to akka's global log level. It is off by default, as the root logger is at INFO, and costs nothing when off since log.debug is a macro guarded by isDebugEnabled. The directive wraps the route outside handleRejections, so rejected requests are logged too, with the status they were answered with. Closes ergoplatform#1909
Commented-out logger element so the switch is discoverable.
Attaches a logback ListAppender to the service logger and asserts on what is emitted: one line per served query with method, URI, status and duration; the query string included and unmatched paths logged with the status they were answered with; nothing logged below DEBUG; and the response body unchanged with logging on and off.
|
On the red CI — it is not this PR.
The same CI round on #2455 — a different branch, touching only I worked the failure through in #2455 (comment there) — short version: a bare |
|
Correction: the cause I pointed at above — What still holds here is only the observable part: |
Closes #1909.
Relation to #1911
@pragmaxim opened #1911 for this in 2022. @kushti's review question there was:
That PR needed
akka-slf4jplusakka.loglevel = "DEBUG"inapplication.confbecause it logged throughDebuggingDirectives.logRequest, which goes via akka'sLoggingAdapterand its event stream.Both of those have since landed in master for other reasons —
build.sbt:332and theakka { ... }block inapplication.conf. So the question is moot on the dependency side, but the mechanism is still worth avoiding: logging through the akka event stream means the verbosity of the node's HTTP log is coupled to akka's global log level, and turning it up brings along everything else akka has to say at DEBUG.This PR logs through
ScorexLogging, like the rest of the codebase, so nothing new is added tobuild.sbtand no global akka setting changes.The change
A single
Directive0wrapping the composite route inErgoHttpService:method, relative URI (path and query string), response status, elapsed time.
Notes on the choices:
handleRejections, so rejected and failed requests are logged too, with the status they were finally answered with. Inside the rejection handler they would never reachmapResponse./wallet/restore, a password on/wallet/unlock, a seed on/wallet/init— and responses can be large. Method, URI, status and duration are what makes API access diagnosable.ScorexLoggingextendsStrictLogging, whoselog.debugis a macro guarded byisDebugEnabled, so the interpolated string is not built unless the logger is actually at DEBUG.logback.xmlis atINFO. A commented-out<logger>element is added there so the switch is discoverable:That also means verbosity is per-logger and under the operator's control, rather than tied to akka's level.
Tests
New
ErgoHttpServiceSpecattaches a logbackListAppenderto the service's logger and asserts on what is actually emitted:GET /emission/at/100 - 200 in <n> ms;sbt "testOnly org.ergoplatform.http.routes.ErgoHttpServiceSpec"— 4 tests, green.