[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: |
|
||||||||||||||||
| 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:
|