[OKAPI-872] Better structure for Okapi logs Created: 20/Mar/20  Updated: 13/Oct/20  Resolved: 21/Sep/20

Status: Closed
Project: Okapi
Components: None
Affects versions: None
Fix versions: 4.2.0

Type: Task Priority: P2
Reporter: Jakub Skoczen Assignee: Mikhail Fokanov
Resolution: Done Votes: 0
Labels: platform-backlog
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Issue links:
Relates
relates to FOLIO-2511 SPIKE: investigate JSON layout to Oka... Closed
relates to OKAPI-871 PoC: structured logging with JSON in ... Closed
relates to OKAPI-902 Update log4j2 configuration in Debian... Closed
Sprint: CP: sprint 92, CP: sprint 94, CP: sprint 95, CP: sprint 96, CP: sprint 97
Story Points: 2
Development Team: Core: Platform

 Description   

Context

Okapi logging is currently somewhat inconsistently implemented across the classes. A logfile sample using the default pattern layout %d{ISO8601} %-5p %-20.20C{1} %m%n:

2020-03-20T20:56:37,556 INFO  OkapiClient          254785/circulation RES 204 24806us okapiClient http://10.36.1.155:9138/circulation/request-scheduled-notices-processing
2020-03-20T20:56:37,557 INFO  TenantManager        wait for lock diku_mod-circulation-18.1.0-SNAPSHOT.535_4 returned
2020-03-20T20:56:37,557 INFO  TenantManager        setTimer delay 120000
2020-03-20T20:56:37,557 INFO  TenantManager        timer call succeeded to module mod-circulation-18.1.0-SNAPSHOT.535 for tenant diku
2020-03-20T20:56:37,914 INFO  TenantManager        handleTimer tenant diku module mod-circulation-18.1.0-SNAPSHOT.535 seq1 5
2020-03-20T20:56:37,914 INFO  TenantManager        timer call start module mod-circulation-18.1.0-SNAPSHOT.535 for tenant diku
2020-03-20T20:56:37,914 INFO  ProxyService         syscall http://10.36.1.155:9175/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,915 INFO  OkapiClient          395377/circulation REQ okapiClient diku HEAD http://10.36.1.155:9175/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,915 INFO  TenantManager        wait for lock diku_mod-circulation-18.1.0-SNAPSHOT.535_5
2020-03-20T20:56:37,915 INFO  TenantManager        handleTimer done no 1
2020-03-20T20:56:37,917 INFO  OkapiClient          395377/circulation RES 202 1736us okapiClient http://10.36.1.155:9175/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,917 INFO  ProxyService         syscall http://10.36.1.155:9138/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,917 INFO  OkapiClient          543001/circulation REQ okapiClient diku POST http://10.36.1.155:9138/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,921 INFO  ProxyContext         543001/circulation;503819/configurations REQ 172.17.0.9:41142 diku GET /configurations/entries  mod-authtoken-2.5.0-SNAPSHOT.64 mod-configuration-5.4.0-SNAPSHOT.68
2020-03-20T20:56:37,921 INFO  ProxyService         Request headers size=3107
2020-03-20T20:56:37,921 INFO  ProxyService         Accept: application/json, text/plain
2020-03-20T20:56:37,921 INFO  ProxyService         host: 10.36.1.155:9130
2020-03-20T20:56:37,921 INFO  ProxyService         user-agent: Vert.x-WebClient/3.8.4
2020-03-20T20:56:37,921 INFO  ProxyService         X-Okapi-Match-Path-Pattern: /*
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-Module-Permissions: {}
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-Permissions-Required: configuration.entries.collection.get
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-Request-Id: 543001/circulation;503819/configurations
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-request-ip: 172.17.0.9
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-request-method: GET
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-request-timestamp: 1584737797921
2020-03-20T20:56:37,922 INFO  ProxyService         X-Okapi-Tenant: diku
2020-03-20T20:56:37,923 INFO  ProxyService         X-Okapi-Token: eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJVTkRFRklORURfVVNFUl9fMTAuMzYuMS4xNTU6MzgzNTZfXzIwMjAtMDMtMjBUMjA6NTY6MzcuOTE2KzAwMDAiLCJtb2R1bGUiOiJtb2QtY2lyY3VsYXRpb24tMTguMS4wLVNOQVBTSE9ULjUzNSIsImV4dHJhX3Blcm1pc3Npb25zIjpbImNpcmN1bGF0aW9uLXN0b3JhZ2UubG9hbnMuaXRlbS5wdXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLmxvYW5zLml0ZW0uZ2V0IiwiY2lyY3VsYXRpb24tc3RvcmFnZS5sb2Fucy5jb2xsZWN0aW9uLmdldCIsImNpcmN1bGF0aW9uLnJ1bGVzLmxvYW4tcG9saWN5LmdldCIsImNpcmN1bGF0aW9uLnJ1bGVzLnJlcXVlc3QtcG9saWN5LmdldCIsImNpcmN1bGF0aW9uLXN0b3JhZ2UucmVxdWVzdHMuY29sbGVjdGlvbi5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLnJlcXVlc3RzLml0ZW0ucHV0IiwiaW52ZW50b3J5LXN0b3JhZ2UuaXRlbXMuaXRlbS5wdXQiLCJpbnZlbnRvcnktc3RvcmFnZS5pdGVtcy5pdGVtLmdldCIsImludmVudG9yeS1zdG9yYWdlLml0ZW1zLmNvbGxlY3Rpb24uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UubG9jYXRpb25zLml0ZW0uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UubG9jYXRpb25zLmNvbGxlY3Rpb24uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UubG9jYXRpb24tdW5pdHMuaW5zdGl0dXRpb25zLml0ZW0uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UubG9jYXRpb24tdW5pdHMuY2FtcHVzZXMuaXRlbS5nZXQiLCJpbnZlbnRvcnktc3RvcmFnZS5sb2NhdGlvbi11bml0cy5saWJyYXJpZXMuaXRlbS5nZXQiLCJpbnZlbnRvcnktc3RvcmFnZS5ob2xkaW5ncy5jb2xsZWN0aW9uLmdldCIsImludmVudG9yeS1zdG9yYWdlLmhvbGRpbmdzLml0ZW0uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UuaW5zdGFuY2VzLmNvbGxlY3Rpb24uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UuaW5zdGFuY2VzLml0ZW0uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2UubWF0ZXJpYWwtdHlwZXMuaXRlbS5nZXQiLCJpbnZlbnRvcnktc3RvcmFnZS5tYXRlcmlhbC10eXBlcy5jb2xsZWN0aW9uLmdldCIsImludmVudG9yeS1zdG9yYWdlLnNlcnZpY2UtcG9pbnRzLmNvbGxlY3Rpb24uZ2V0IiwiaW52ZW50b3J5LXN0b3JhZ2Uuc2VydmljZS1wb2ludHMuaXRlbS5nZXQiLCJpbnZlbnRvcnktc3RvcmFnZS5sb2FuLXR5cGVzLml0ZW0uZ2V0IiwidXNlcnMuaXRlbS5nZXQiLCJ1c2Vycy5jb2xsZWN0aW9uLmdldCIsInByb3hpZXNmb3IuY29sbGVjdGlvbi5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLmxvYW4tcG9saWNpZXMuaXRlbS5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLmxvYW4tcG9saWNpZXMuY29sbGVjdGlvbi5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLnJlcXVlc3QtcG9saWNpZXMuaXRlbS5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLmZpeGVkLWR1ZS1kYXRlLXNjaGVkdWxlcy5pdGVtLmdldCIsImNpcmN1bGF0aW9uLXN0b3JhZ2UuZml4ZWQtZHVlLWRhdGUtc2NoZWR1bGVzLmNvbGxlY3Rpb24uZ2V0IiwiY29uZmlndXJhdGlvbi5lbnRyaWVzLmNvbGxlY3Rpb24uZ2V0IiwiY2lyY3VsYXRpb24ucnVsZXMubm90aWNlLXBvbGljeS5nZXQiLCJjaXJjdWxhdGlvbi1zdG9yYWdlLnBhdHJvbi1ub3RpY2UtcG9saWNpZXMuaXRlbS5nZXQiLCJzY2hlZHVsZWQtbm90aWNlLXN0b3JhZ2Uuc2NoZWR1bGVkLW5vdGljZXMuY29sbGVjdGlvbi5kZWxldGUiLCJzY2hlZHVsZWQtbm90aWNlLXN0b3JhZ2Uuc2NoZWR1bGVkLW5vdGljZXMuaXRlbS5wb3N0IiwicGF0cm9uLW5vdGljZS5wb3N0IiwiYW5vbnltaXplLXN0b3JhZ2UtbG9hbnMucG9zdCIsImFjY291bnRzLmNvbGxlY3Rpb24uZ2V0IiwiZmVlZmluZWFjdGlvbnMuY29sbGVjdGlvbi5nZXQiXSwicmVxdWVzdF9pZCI6IjM5NTM3N1wvY2lyY3VsYXRpb24iLCJ0ZW5hbnQiOiJkaWt1In0.T8Ydz1VFEApF7LeR04uzJBRIaXUeslj0FoX9Uob3-3E
2020-03-20T20:56:37,923 INFO  ProxyService         X-Okapi-Url: http://10.36.1.155:9130
2020-03-20T20:56:37,923 INFO  ProxyService         X-Okapi-User-Id: 
2020-03-20T20:56:37,924 INFO  ProxyContext         543001/circulation;503819/configurations RES 202 3238us mod-authtoken-2.5.0-SNAPSHOT.64 http://10.36.1.155:9175/configurations/entries?query=module%3D%3D%22LOAN_HISTORY%22%20and%20configName%3D%3D%22loan_history%22&limit=1
2020-03-20T20:56:37,924 INFO  ProxyService         Request headers size=3091
2020-03-20T20:56:37,924 INFO  ProxyService         Accept: application/json, text/plain
2020-03-20T20:56:37,924 INFO  ProxyService         host: 10.36.1.155:9130
2020-03-20T20:56:37,924 INFO  ProxyService         user-agent: Vert.x-WebClient/3.8.4
2020-03-20T20:56:37,924 INFO  ProxyService         X-Okapi-Match-Path-Pattern: /configurations/entries
2020-03-20T20:56:37,924 INFO  ProxyService         X-Okapi-Permissions: ["configuration.entries.collection.get"]
2020-03-20T20:56:37,925 INFO  ProxyService         X-Okapi-Request-Id: 543001/circulation;503819/configurations
2020-03-20T20:56:37,925 INFO  ProxyService         X-Okapi-request-ip: 172.17.0.9
2020-03-20T20:56:37,925 INFO  ProxyService         X-Okapi-request-method: GET
2020-03-20T20:56:37,935 INFO  OkapiClient          543001/circulation RES 500 17524us okapiClient http://10.36.1.155:9138/circulation/scheduled-anonymize-processing
2020-03-20T20:56:37,935 WARN  ProxyService         POST request for mod-circulation-18.1.0-SNAPSHOT.535 /circulation/scheduled-anonymize-processing failed with Failed to decode:No content to map due to end-of-input
 at [Source: (String)""; line: 1, column: 0]
io.vertx.core.json.DecodeException: Failed to decode:No content to map due to end-of-input
 at [Source: (String)""; line: 1, column: 0]
	at io.vertx.core.json.jackson.JacksonCodec.fromParser(JacksonCodec.java:97)
	at io.vertx.core.json.jackson.JacksonCodec.fromString(JacksonCodec.java:57)
	at io.vertx.core.json.JsonObject.fromJson(JsonObject.java:971)
	at io.vertx.core.json.JsonObject.<init>(JsonObject.java:54)
	at org.folio.circulation.domain.ConfigurationRepository.getFirstConfiguration(ConfigurationRepository.java:69)
	at org.folio.circulation.support.Result.lambda$map$18(Result.java:351)
	at org.folio.circulation.support.Result.next(Result.java:335)
	at org.folio.circulation.support.Result.map(Result.java:351)
	at org.folio.circulation.domain.ConfigurationRepository.lambda$loanHistoryConfiguration$6(ConfigurationRepository.java:58)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java:308)
	at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:295)
	at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:270)
	at io.vertx.ext.web.client.impl.predicate.PredicateInterceptor.handle(PredicateInterceptor.java:69)
	at io.vertx.ext.web.client.impl.predicate.PredicateInterceptor.handle(PredicateInterceptor.java:32)
	at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:267)
	at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:277)
	at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:238)
	at io.vertx.ext.web.client.impl.HttpContext.lambda$null$2(HttpContext.java:367)
	at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:369)
	at io.vertx.core.impl.WorkerContext.lambda$wrapTask$0(WorkerContext.java:35)
	at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.fasterxml.jackson.databind.exc.MismatchedInputException: No content to map due to end-of-input
 at [Source: (String)""; line: 1, column: 0]
	at com.fasterxml.jackson.databind.exc.MismatchedInputException.from(MismatchedInputException.java:59)
	at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:4146)
	at com.fasterxml.jackson.databind.ObjectMapper._readValue(ObjectMapper.java:3972)
	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2277)
	at io.vertx.core.json.jackson.JacksonCodec.fromParser(JacksonCodec.java:95)
	... 28 more

A couple of comments based on attempting to parse these logs into a more structured JSON format:

  • Some classes (ProxyService, in particular) emit many log events for one request. Without any data to tie them together, analysis can be difficult.
  • The request ID is useful in a number of different contexts. Perhaps it would be useful to put it in the MDC so it can be reliably extracted.
  • The ProxyService class puts stack traces in a message, rather than relying on exception handling for logging. If you throw an exception, it can be picked up with %xEx in the log layout.
  • Perhaps some DEBUG information is still being logged at the INFO level (see ProxyService). It would help to have better consistency about what should be logged at which level. It is, I think, reasonable to want to log at the INFO level in a production system at this time.

Generated at Thu Feb 08 23:21:16 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.