Logging to a Central Database

Introduction

Oracle Health Insurance applications and the runtime technology stack support various logging capabilities.

Examples of logs that are currently written:

Security log: to track (failed) login attempts.
Protected Health Information (PHI) log: to track which health insurance payer employee viewed specific member related information.
Dynamic Logic log: to track dynamic logic execution.
Application log: contains informational messages, warnings and errors. This log contains all messages that are logged by Oracle Health Insurance applications that are not in the Security log, the PHI log or the Dynamic Logic log.
JVM GC log: garbage collection statistics.
Server output logs: detailed technical information about the state of specific JVM processes as written by the application server.

All Oracle Health Insurance applications use the Logback framework for logging data. Logback supports a wide variety of 'log appenders'; the best known appender is probably the file appender that is used by each JVM that runs the application to write log files to disk. In the Logback configuration, the logging level for specific loggers (e.g. per package or even per class) can be adjusted in order to get more detailed diagnostic data from the system.

The Oracle Health Insurance Logback Database Appender

When each JVM writes data to separate log files, it is relatively hard to get a complete overview. Starting with the 3.18.1.x releases of Oracle Health Insurance applications, the following Oracle Health Insurance application logs can be directly streamed into database tables:

Log	Database Table	HTTP API resource
PHI log	log_phi_events	/generic/logphievents
Dynamic Logic log	log_dylo_events	/generic/logdyloevents
Application log	log_application_events	/generic/logapplicationevents

Log

Database Table

HTTP API resource

PHI log

log_phi_events

/generic/logphievents

Dynamic Logic log

log_dylo_events

/generic/logdyloevents

Application log

log_application_events

/generic/logapplicationevents

The final column specifies which HTTP API resource can be used to access and / or query logged messages.

For efficiency reasons, Oracle Health Insurance applications come with a specific Logback database appender. Loggers initially write to a file-backed buffer queue. From the file-backed queue log events are (eventually) persisted to the database.

This appender assumes that log messages are formatted as JSON documents with a specific structure. For JSON encoding the well-known Logstash Logback Encoder is used. If no encoder configuration is specified default settings are applied that match the following configuration:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <providers>
    <mdc/>
    <context/>
    <nestedField>
      <fieldName>markers</fieldName>
      <providers>
        <logstashMarkers/>
      </providers>
    </nestedField>
    <nestedField>
      <fieldName>arguments</fieldName>
      <providers>
        <arguments/>
      </providers>
    </nestedField>
    <pattern>
      { "ohiLevel": "%ohiLevel" }
    </pattern>
    <fieldNames>
      <timestamp>timestamp</timestamp>
    </fieldNames>
  </providers>
</encoder>

If it is desirable to adjust the default settings make sure to retain the defaults that Oracle Health Insurance applications rely on. The following example adds a specific configuration for stack traces:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <providers>
    <mdc/>
    <context/>
    <nestedField>
      <fieldName>markers</fieldName>
      <providers>
        <logstashMarkers/>
      </providers>
    </nestedField>
    <nestedField>
      <fieldName>arguments</fieldName>
      <providers>
        <arguments/>
      </providers>
    </nestedField>
    <pattern>
      { "ohiLevel": "%ohiLevel" }
    </pattern>
    <fieldNames>
      <timestamp>timestamp</timestamp>
    </fieldNames>
    <stackTrace>
      <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
        <maxDepthPerThrowable>30</maxDepthPerThrowable>
        <maxLength>2048</maxLength>
        <shortenedClassNameLength>20</shortenedClassNameLength>
        <exclude>^sun\.reflect\..*\.invoke</exclude>
        <exclude>^net\.sf\.cglib\.proxy\.MethodProxy\.invoke</exclude>
        <rootCauseFirst>true</rootCauseFirst>
      </throwableConverter>
    </stackTrace>
  </providers>
</encoder>

Other configuration options for the Oracle Health Insurance Logback Database Appender are listed in the following table:

Parameter	Explanation	Required?
connectionSource	For the Database Appender to work it needs access to a database. Make sure to only use a JNDI Connection Source. If a connection source is not specified the application will not start; it will throw an IllegalStateException with message "OhiAppender cannot function without a connection source"	Yes
logType	Currently supported log types are "phi", "dylo" and "application". If a log type is not specified the application will not start; it will throw an IllegalStateException with message "OhiAppender cannot function without a specific log type".	Yes
bufferDir	The Database Appender buffers log messages in a file-backed queue or buffer. Queue files will be written in the specified directory. If a bufferDir is not specified the application will use the value of system property "java.io.tmpdir". If the application cannot write to the configured directory then the application will not start; it will throw an IllegalStateException with message "Cannot write to path <path>"	Yes
drainInterval	By default the file-backed queue will be drained every 5 milliseconds. This value can be overwritten if desired. The minimum is 1 millisecond. If a drain interval below 1 millisecond is specified the application will not start; it will throw an IllegalStateException with message "Invalid timeout to drain queue specified: <specified_time_interval>"	No
drainBatchSize	By default, messages from the file-backed queue will be persisted in batches with a max size of 2000. This value can be overwritten if desired. The minimum batch size is 1 (note that such a value is extremely inefficient!). If a batch size smaller than 1 is specified the application will not start; it will throw an IllegalStateException with message "Invalid batch size for draining queue specified: <specified_time_interval>"	No
rollCycle	Files for the file-backed queue roll over periodically. The files that are no longer used are removed automatically in order to limit disk space use. This parameter allows specification of the roll cycle. The default value is HOURLY, that allows storing 256 million entries per hour (disk space permitting). The alternative value is DAILY (4 billion entries per day). Contact Oracle Health Insurance development in the unusual case the buffer should accommodate larger amounts of log entries.	No
duplicateDuration	Setting a value for this parameter filters duplicate events with level ERROR to prevent the system from logging many occurrences of the same ERROR in a short period of time which may cause its logging capability to be 'flooded'. An ERROR event is considered to be a duplicate if an event for the same logger and with the same (raw) message was logged in the last 'duplicateDuration' milliseconds. This is only applicable for ERROR messages in the Application log. It is disabled by default. Setting this value to 300000 milliseconds will log an error message once per thread and will suppress the same error message logged in that thread for the next 5 minutes.	No

Parameter

Explanation

Required?

connectionSource

For the Database Appender to work it needs access to a database. Make sure to only use a JNDI Connection Source.

If a connection source is not specified the application will not start; it will throw an IllegalStateException with message "OhiAppender cannot function without a connection source"

Yes

logType

Currently supported log types are "phi", "dylo" and "application".

If a log type is not specified the application will not start; it will throw an IllegalStateException with message "OhiAppender cannot function without a specific log type".

Yes

bufferDir

The Database Appender buffers log messages in a file-backed queue or buffer. Queue files will be written in the specified directory.

If a bufferDir is not specified the application will use the value of system property "java.io.tmpdir". If the application cannot write to the configured directory then the application will not start; it will throw an IllegalStateException with message "Cannot write to path <path>"

Yes

drainInterval

By default the file-backed queue will be drained every 5 milliseconds. This value can be overwritten if desired. The minimum is 1 millisecond.

If a drain interval below 1 millisecond is specified the application will not start; it will throw an IllegalStateException with message "Invalid timeout to drain queue specified: <specified_time_interval>"

drainBatchSize

By default, messages from the file-backed queue will be persisted in batches with a max size of 2000. This value can be overwritten if desired. The minimum batch size is 1 (note that such a value is extremely inefficient!).

If a batch size smaller than 1 is specified the application will not start; it will throw an IllegalStateException with message "Invalid batch size for draining queue specified: <specified_time_interval>"

rollCycle

Files for the file-backed queue roll over periodically. The files that are no longer used are removed automatically in order to limit disk space use. This parameter allows specification of the roll cycle. The default value is HOURLY, that allows storing 256 million entries per hour (disk space permitting). The alternative value is DAILY (4 billion entries per day).

Contact Oracle Health Insurance development in the unusual case the buffer should accommodate larger amounts of log entries.

duplicateDuration

Setting a value for this parameter filters duplicate events with level ERROR to prevent the system from logging many occurrences of the same ERROR in a short period of time which may cause its logging capability to be 'flooded'.

An ERROR event is considered to be a duplicate if an event for the same logger and with the same (raw) message was logged in the last 'duplicateDuration' milliseconds.

This is only applicable for ERROR messages in the Application log. It is disabled by default.

Setting this value to 300000 milliseconds will log an error message once per thread and will suppress the same error message logged in that thread for the next 5 minutes.

The log type parameter for the appender drives

proper filtering of log messages, e.g. to ensure that PHI log messages do not show up in the application log;
how log messages are stored in the database.

The following paragraphs list the Logback configuration for each of these logs.

Please note that:

in the below Logback configuration the encoder is omitted, implying that the Oracle Health Insurance default settings are used;
the buffer directory lists imaginary locations "/writable/log/storage/buffer/…". Make sure that the actual buffer directory that is configured is writable. If that is not the case then the application will log an IllegalStateException in the managed server’s log.

Logging Dynamic Logic execution

Sample configuration for an Oracle Health Insurance appender for Dynamic Logic execution logging:

<configuration debug="true" scan="true" scanPeriod="60 seconds">
 <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

 <conversionRule conversionWord="ohiLevel"
  converterClass="com.oracle.healthinsurance.utils.logging.logback.OhiLogLevelConverter"/>

 <appender name="dyloAppender"
  class="com.oracle.healthinsurance.loggingsupport.appender.impl.OhiAppender">
     <connectionSource class="ch.qos.logback.core.db.JNDIConnectionSource">
         <jndiLocation>jdbc/policiesUserOhiApplicationDS</jndiLocation>
     </connectionSource>
     <logType>dylo</logType>
     <bufferDir>/writable/log/storage/buffer/dylo</bufferDir>
 </appender>

 <root level="info">
     <appender-ref ref="dyloAppender" />
 </root>
</configuration>

Note that all Dynamic Logic scripts are in package namespace "ohi.dynamiclogic". Before any statements for that package are logged the following logger needs to be added:

<logger name="ohi.dynamiclogic" level="trace"/>

Logging access to Protected Health Information (PHI)

Sample configuration for an Oracle Health Insurance appender for PHI logging:

<configuration debug="true" scan="true" scanPeriod="60 seconds">
 <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

 <conversionRule conversionWord="ohiLevel"
  converterClass="com.oracle.healthinsurance.utils.logging.logback.OhiLogLevelConverter"/>

 <appender name="phiAppender"
  class="com.oracle.healthinsurance.loggingsupport.appender.impl.OhiAppender">
     <connectionSource class="ch.qos.logback.core.db.JNDIConnectionSource">
         <jndiLocation>jdbc/policiesUserOhiApplicationDS</jndiLocation>
     </connectionSource>
     <logType>phi</logType>
     <bufferDir>/writable/log/storage/buffer/phi</bufferDir>
 </appender>

 <root level="info">
     <appender-ref ref="phiAppender" />
 </root>
</configuration>

Application log

Sample configuration for an Oracle Health Insurance appender for remaining log messages (that should not end up in the Security log, the PHI log or the Dynamic Logic log):

<configuration debug="true" scan="true" scanPeriod="60 seconds">
 <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>

 <conversionRule conversionWord="ohiLevel"
  converterClass="com.oracle.healthinsurance.utils.logging.logback.OhiLogLevelConverter"/>

 <appender name="applicationAppender"
  class="com.oracle.healthinsurance.loggingsupport.appender.impl.OhiAppender">
     <connectionSource class="ch.qos.logback.core.db.JNDIConnectionSource">
         <jndiLocation>jdbc/policiesUserOhiApplicationDS</jndiLocation>
     </connectionSource>
     <logType>application</logType>
     <bufferDir>/writable/log/storage/buffer/application</bufferDir>
 </appender>

 <root level="info">
     <appender-ref ref="applicationAppender" />
 </root>
</configuration>

Tracking the Oracle Health Insurance appender’s status

The Oracle Health Insurance Logback Database Appender can write messages about its own state to the Oracle Health Insurance logs. Its status can be tracked using Logback status listeners and by redirecting messages that it writes to "Standard Out" and "Standard Error" to the server log.

Enable LogBack Status listeners for the Oracle Health Insurance Database Appender

Enable the LogBack status listener by:

Setting the Logback configuration debug flag to true as was done in the samples above.
Attaching a status listener as in the following example:

<configuration>
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
  ...
</configuration>

Refer to the Logback documentation for a complete overview of capabilities. The Oracle Health Insurance Logback Database Appender writes LogBack status messages during initialization and shutdown.

Tracking the logger’s status using LogBack

The Oracle Health Insurance Database Appender makes use of separate threads to write messages from the file-backed queue to the database. Within these threads, diagnostic messages can be written by enabling LogBack loggers. Make sure to log the messages about the Oracle Health Insurance Database Appender to a different appender. The following is a sample LogBack configuration for tracking the Oracle Health Insurance Database Appender, the messages are written to a specific file appender:

<conversionRule conversionWord="ohiLevel"
 converterClass="com.oracle.healthinsurance.utils.logging.logback.OhiLogLevelConverter"/>

<appender name="fileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <encoder>
        <pattern>%d{ISO8601} %ohiLevel %logger{3} - %m%n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>target/ohiAppenderFile-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>100MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
</appender>

<logger name="com.oracle.healthinsurance.loggingsupport.appender.impl.QueueFileListener"
 level="debug" additivity="false">
    <appender-ref ref="fileAppender"/>
</logger>
<logger name="com.oracle.healthinsurance.loggingsupport.appender.impl.OhiAppender"
 level="debug" additivity="false">
    <appender-ref ref="fileAppender"/>
</logger>
<logger name="com.oracle.healthinsurance.loggingsupport.appender.impl.LoggingEventBatchPersister"
 level="debug" additivity="false">
    <appender-ref ref="fileAppender"/>
</logger>

Centrally stored logged data can be accessed using HTTP API resources. The following paragraphs provide details for these as well as a number of examples.

Retrieving log messages

Note that users need to be properly authorized before HTTP API resources can be accessed.

The default representation for each resource can be retrieved from the metadata specification or a sample can be fetched by executing a GET request to any of the resources mentioned above. For example, the default representation for application log events looks like the following example:

{"id": 96558,
 "application": "authorizations",
 "applicationVersion": "3.18.1.0.0",
 "eventLevel": "ERROR",
 "eventLogger": "c.o.h.d.d.i.c.p.DataReplicationTargetSynchronizationTaskTypeProcessor",
 "eventMessage": "Failed to retrieve and / or store events, closing data replication extraction task",
 "eventThread": "[STANDBY] ExecuteThread: '18' for queue: 'weblogic.kernel.Default (self-tuning)'",
 "hostName": "a_host",
 "instanceName": "authorizations_node1",
 "instanceType": "an_instance",
 "links": [
  {"href": "http://localhost:27041/api/generic/logapplicationevents/96558",
   "rel": "self"
  }
 ],
 "eventTimestamp": {
   "value": "2018-01-11T17:42:27.13+01:00"
  },
 "persistedTimestamp": {
   "value": "2018-01-11T17:42:31.304+01:00"
  }
}

Note that many attributes will be repeated for other logged messages as well.

When querying log messages, make sure to always filter on eventDate or persistedTimestamp as these are indexed. As the number of log messages grows, using these as access path makes sure request response times remain acceptable.

Example: checking for warnings and errors in the Application log

The Query API can be used to look for specific log messages. The following GET request returns errors or warnings in a specific hour on a specific day, ordered by the timestamp on which the message was logged:

/generic/logapplicationevents?q=eventLevel.in('WARN','ERROR') \
.and.eventDate.gt('2018-01-11T17:00:00').and.eventDate.lt('2018-01-12T18:00:00') \
&orderBy=eventTimestamp:asc

When it is executed using the following Accept header:

application/vnd.oracle.insurance.resource+json; fields="eventMessage|eventTimestamp"

the results should look like the following example, a more concise version of the previous application log event’s sample:

{"id": 96558,
 "eventMessage": "Failed to retrieve and / or store events, closing data replication extraction task",
 "links": [
  {"href": "http://localhost:27041/api/generic/logapplicationevents/96558",
   "rel": "self"
  }
 ],
 "eventTimestamp": {
   "value": "2018-01-11T17:42:27.13+01:00"
  }
}

Note the difference between eventDate and eventTimeStamp:

The precision for the eventDate is limited to seconds. Specifically for executing such queries in an efficient manner, the eventDate is indexed.
The precision for the eventTimestamp includes microseconds as well as time zone information.

Checking access to PHI data

An entry to the PHI log is written when a system user accesses an insured member’s personal identifiable information, whether this is done through a web service or the application’s user interface.

Following Dynamic Logic execution

The Dynamic Logic log can be used to inspect Dynamic Logic execution.

For every Dynamic Logic execution a unique execution ID is generated that all messages logged during the execution will carry.

Sample messages that are logged for executing a Dynamic Logic script (edited for readability):

{
  "message" : "execution starts",
  "logger_name" : "ohi.dynamiclogic",
  "level" : "TRACE",
  "markers" : {
    "scriptexecutionid" : "da2e6719-e5d2-4112-85b9-4321929aeed9"
  }
}
{
  "message" : "Binding foo set to bar",
  "logger_name" : "ohi.dynamiclogic",
  "level" : "TRACE",
  "markers" : {
    "scriptexecutionid" : "da2e6719-e5d2-4112-85b9-4321929aeed9"
  }
}
{
  "message" : "result: true of type: class java.lang.Boolean",
  "logger_name" : "ohi.dynamiclogic",
  "level" : "TRACE",
  "markers" : {
    "scriptexecutionid" : "da2e6719-e5d2-4112-85b9-4321929aeed9"
  }
}
{
  "message" : "execution completed",
  "logger_name" : "ohi.dynamiclogic",
  "level" : "TRACE",
  "markers" : {
    "scriptexecutionid" : "da2e6719-e5d2-4112-85b9-4321929aeed9"
  }
}

Adding Loggers and Setting Log Levels

At startup time, Logback’s basic configuration is initially read from a configuration file. Note that it is expected that a single copy of that configuration is available for all nodes that execute an instance of an Oracle Health Insurance application. For runtime adjustments a "/loggers" HTTP API is available in order to:

Get an overview of custom loggers that were defined using the "/loggers" API by executing a GET request to "/loggers".
Add a logger with a specific log level by executing a POST request to "/loggers".
Update the level of an existing logger by executing a PUT request to "/loggers/{id}".
Unsetting a logger by executing a DELETE request to "/loggers/{id}". In this case, the logger will inherit the log level of its parent.

Note that any changes made via the "/loggers" API are propagated to all nodes that execute an instance of an Oracle Health Insurance application.

For example, for adding a logger for package "com.oracle.healthinsurance.datareplication.service" with level debug, send the following JSON payload:

{"logger": "com.oracle.healthinsurance.datareplication.service"
,"logLevel": "DEBUG"
}

Changes made via the "/loggers" API are not added to the Logback’s configuration file. These changes are durable though and will be re-activated when an Oracle Health Insurance application is restarted. The order in which loggers are initialized at startup is as follows:

Loggers that are specified in the Logback configuration file are created first.
After that logger settings that were defined using the "/loggers" API are applied. Note that these may overwrite settings for loggers that are defined in the Logback configuration file.

Warning:Maintenance of logger settings that were defined using the "/loggers" API is left entirely to the customer.

Using the Diagnostic Context

Oracle Health Insurance applications log data in context. For example:

For Claims processing in Oracle Health Insurance Claims log messages are written in context of the specific claim that is processed making it possible to gather all log messages for a specific claim.
Log messages written while processing Web Service requests can be tracked using a trace ID that is provided in the request. Alternatively, if a trace ID is not provided one will be generated and returned in the response.