[FOLIO-2511] SPIKE: investigate JSON layout to Okapi and RMB logs Created: 13/Mar/20  Updated: 25/Aug/20  Resolved: 25/Aug/20

Status: Closed
Project: FOLIO
Components: None
Affects versions: None
Fix versions: None

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

Issue links:
Relates
relates to OKAPI-871 PoC: structured logging with JSON in ... Closed
relates to RMB-709 structured logging in RMB Closed
relates to OKAPI-872 Better structure for Okapi logs Closed
Requires
is required by FOLIO-2644 SPIKE: Folio logging approach Closed
Sprint: CP: sprint 92, CP: sprint 94, CP: sprint 95, CP: sprint 90, CP: sprint 91
Story Points: 3
Development Team: Core: Platform

 Description   

Goal

Investigate if JSON format can be used to provider structured logs in FOLIO, both for Okapi and backend modules (with RMB providing default logging configuration).

If successful JSON format will be used to provide structured data in the logs. The following fields are candidates for inclusion:

  • logLevel
  • timestamp
  • message
  • stacktrace - plain text joined by \n symbol (for errors)
  • tenantId
  • moduleId (e.g mod-authtoken-1.2.3)
  • requestId
  • userId
  • uri (e.g /inventory-storage/instances) e.g an HTTP API path
  • queryString as a separate element to capture HTTP parameters
  • code (e.g 200, 400, 500) e.g an HTTP response code
  • duration (e.g 1234, in msecs) time it took to complete an operation
  • sql SQL Query

A complete set is still being discussed, see https://folio-org.atlassian.net/wiki/pages/viewpage.action?pageId=1776544

Caveats

FOLIO DevOps team has been experimenting with JSON logging configuration and have seen the following issues trying to enable JSON logging:

  • poor performance when using the "location" information (like class)
  • disappearance of existing structured fields when adding custom fields

See details of this investigation below.

Implementation

We will put utilities (e.g FolioLoggingContext) and default log4j config in a shared project (okapi-common since it's used by RMB and will make the classes available in all RMB projects).

We will let module developers know to remove their existing log4j configuration to make use of the default one. They will be also able to use the default one as a starting point and put in additional customize.



 Comments   
Comment by Wayne Schneider [ 13/Mar/20 ]

JSON logging configuration:

    <Configuration status="WARN" monitorInterval="30">
      <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
          <JSONLayout compact="true" eventEOL="true"/>
        </Console>
      </Appenders>
      <Loggers>
        <Root level="INFO">
          <AppenderRef ref="Console"/>
        </Root>
      </Loggers>
    </Configuration>

Okapi log output (pretty-printed for clarity):

  {
    "thread": "vert.x-eventloop-thread-1",
    "level": "INFO",
    "loggerName": "okapi",
    "message": "X-Okapi-Request-Id: 177027/circulation;918494/configurations",
    "endOfBatch": false,
    "loggerFqcn": "org.apache.logging.log4j.spi.AbstractLogger",
    "threadId": 102,
    "instant": {
      "epochSecond": 1583852446,
      "nanoOfSecond": 282000000
    },
    "threadPriority": 5
  }

RMB log output (mod-inventory-storage-18.2.3):

  {
    "timeMillis": 1583855032670,
    "thread": "main",
    "level": "INFO",
    "loggerName": "org.folio.rest.tools.messages.Messages",
    "message": "Loading messages from /infra-messages/APIMessages_de.properties ................................",
    "endOfBatch": false,
    "loggerFqcn": "io.vertx.core.logging.Logger",
    "threadId": 1,
    "threadPriority": 5
  }
Comment by Wayne Schneider [ 13/Mar/20 ]

Observations from testing:
Attempting to add location information (class name, file, method, etc.) with locationInfo="true" results in a significant performance hit. See https://logging.apache.org/log4j/2.x/manual/layouts.html#LocationInformation for one possible explanation. This does not explain why including the class name in a PatternLayout does not appear to affect performance.

Attempting to add a custom field (either a lookup or a constant) as documented (https://logging.apache.org/log4j/2.x/manual/layouts.html#JSONLayout) does not work as expected for Okapi. You end up with log entries like this:

  {
    "logEvent": "setTimer delay 432000000",
    "customField1": "custom value"
  }

Note that the log is quite a bit thinner, and structured very differently. This is quite different from the expected behavior, according to the log4j2 documentation.

For RMB, attempting to add a custom field simply doesn't work – the log output is not changed.

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