Uploaded image for project: 'Okapi'
  1. Okapi
  2. OKAPI-872

Better structure for Okapi logs

    XMLWordPrintable

Details

    • CP: sprint 92, CP: sprint 94, CP: sprint 95, CP: sprint 96, CP: sprint 97
    • 2
    • 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.

      TestRail: Results

        Attachments

          Issue Links

            Activity

              People

                mikhail.fokanov Mikhail Fokanov
                jakub Jakub Skoczen
                Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                  Created:
                  Updated:
                  Resolved:

                  TestRail: Runs

                    TestRail: Cases