Skip to content
apryamostanov edited this page Aug 19, 2019 · 19 revisions

Table of contents generated with markdown-toc

Infinite Logging ∞ BlackBox ⬛

Black box is a hardware device in the airplane that keeps record of flight parameters and flight control system operation signals (such as flaps control).
BlackBox annotation acts as a software Black box for your programs helping to recover data that has caused exceptions in User code.

Purpose

BlackBox solution automatically generates Groovy Semantic logging code and injects it into User code during the Compilation stage resulting in a possibility to produce and review exhaustive application runtime data in a form of text files - by the means of developing and using a Groovy Annotation.

In short

BlackBox Annotation automatically injects a lot of logging code into user-defined Groovy methods/constructors without affecting the user program logic.

Granularity of injected code can be defined by the user (programmer) up to:

  • Method Exceptions logging (exception and causing method arguments are logged)
  • Method invocation logging (method arguments and result are logged)
  • Statement-level logging
  • Expression-level logging

Introduction

Foreword

Logging is one of the most important parts of modern applications.

Its significance only increases in case of:

  • Financial environments (consider PCI-DSS and sensitive data logging)
  • Cloud environments (consider logging to Logstash)
  • GDPR

Some scenarios when logging is useful include:

  • Network data exchange (TCP, HTTP, SOAP, REST)
  • Periphery communication (Bluetooth, serial port, USB, etc)
  • IOT (I2C, SPI)
  • Automotive communication (Canbus and its implementations)

The Problem

While at a level of Logging engines (Log4J, JUL, Logback → SLF4J) things are relatively clear, there is a methodological gap in terms of approach and best practices for logging integration into User code as well as its automation.

In short there is no set of rules helping programmers to understand:

  • What to log
  • How to structure the log data
  • When to log
  • Where to place logging code in the application
  • How log can be used on Test and Production environments
  • Why spend time writing logging code

When it comes to automation of logging in Java and Groovy, the things are getting less clear:

  • Groovy provides annotations (@Slf4j, etc) to inject log variable declaration and initialization

That saves just a couple of lines of code. But there is no real way to inject the actual logging code into the application. Programmers have to manually place lines with logging leading to unwanted results:

  • Cluttering the real code base with logging code
  • Unstructured and cluttered log output
  • Chances of misplacing the logging code and missing important output
  • Increase of development time and costs

The Solution

As an Open Source community we are taking an initiative to come up with a new Logging solution addressing these limitations and supporting many additional features.

The "BlackBox" solution helps to address the key questions:

  • What to log:
    • 4 levels of logging:
      • Method exceptions (with arguments causing exception)
      • Method execution (with method arguments, result and exceptions)
      • Statements execution within the method (all Groovy statements are supported)
      • Expression execution and evaluation (all Groovy expressions are supported) - with the resulting object value and class
    • Compile-time metadata:
      • Line numbers
      • Code snippets
  • How to structure the log data
    • Log data is automatically structured into text files according to BlackBox format therefore leaving no room for disambiguation when it comes to interpretation of log data.
  • Where to place logging code in the application
    • Simply add @BlackBox annotation to the method - and the job is done. No need to clutter the actual code with logging lines.
  • How log can be used on Test and Production environments
    • Issue investigation & debugging
    • Performance profiling and optimization
    • Statistics
    • Analytics
    • Monitoring
    • Telemetry
    • Journaling
  • Why spend time writing logging code
    • No more time need to be spent!

Terminology

Logging

Logging is a process of saving structured data on a permanent storage with assumption that it may be used in future. However it is neither known how and when this data will be used neither it is guaranteed that this data is useful.

Logging Engine

Logging Engine is a library that provides an API to save log data.

BlackBox is using Slf4j-compatible Logging Engine API.

❇ Logging Engine does not define neither the structure itself nor API of structuring the log data. Logging Engine defines only structure of log record format (such as adding timestamp and thread information), while the input data comes in its final form from outside of the log engine.

Example Logging Engines are:

  • Log4J
  • Logback
  • Others

We recommend to use Bobbin Slf4j Logging Engine in projects using BlackBox due to its simplicity and performance.

User Code

User Code is a Code written by application programmers for business or other purposes.

Semantic Logging

Semantic-level logging is a technique which helps to trace application execution flow as per code semantic structures such as:

  • Method execution start and end
  • Method arguments and result
  • Statements such as if/else
  • Expressions such as assignment expression

Features

BlackBox is based on Carburetor AST transformation tool.

For comprehensive list of features and technical description please refer to Carburetor Documentation.

We are listing only additional features present in BlackBox.

Compilation Stage

Suppress Exceptions

There are scenarios when it is needed to log exception but suppress (ignore) it without re-throwing. For example when when using User Scripts or in Thread body methods.

In these scenarios @BlackBox annotation supports parameter suppressExceptions that automatically prevents re-throwing of the exception:

    @BlackBox(level = CarburetorLevel.ERROR, suppressExceptions = true)
    void foo() {
        bar()
    }

Above example will be equivalent to:

    void foo() {
        try {
            bar()
        } catch (Exception e) {
            log.error(e) //log exception without re-throwing
        }
    }

Runtime

BlackBox is implementing the handling of Carburetor Runtime events by logging them using Slf4j API.

Below is the example how the runtime execution is logged by BlackBox:

2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|METHOD RESULT:
2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|org.springframework.http.ResponseEntity
2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|<200 OK OK,io.infinite.pigeon.springdatarest.CustomResponse(response:[message:Self test started (2019-02-20 18-29-43-090), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550672982945, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550672983042]),{}>
2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|METHOD END: applyPlugin.conf.plugins.input.rest.SelfTest(20,1,62,2)
2019-02-21 15:43:51:128|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:43:51:154|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT:
2019-02-21 15:43:51:154|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap
2019-02-21 15:43:51:155|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-43-51-148), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749431056, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749431124]
2019-02-21 15:43:51:155|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:48:34:536|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:48:34:571|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT:
2019-02-21 15:48:34:571|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap
2019-02-21 15:48:34:572|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-48-34-564), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749714444, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749714530]
2019-02-21 15:48:34:572|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:53:58:299|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:53:58:326|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT:
2019-02-21 15:53:58:326|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap
2019-02-21 15:53:58:327|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-53-58-318), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750038217, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750038295]
2019-02-21 15:53:58:328|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:58:35:032|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:58:35:061|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT:
2019-02-21 15:58:35:061|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap
2019-02-21 15:58:35:062|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-58-35-052), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750314954, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750315028]
2019-02-21 15:58:35:063|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)
2019-02-21 15:54:11:486|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|EXCEPTION (first occurrence):
2019-02-21 15:54:11:492|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|a64aceed-8e4c-4d4b-8030-0c23bc3b3f0d
2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|java.lang.NullPointerException
	at io.infinite.pigeon.threads.SenderThread.sendMessage(SenderThread.groovy:98)
	at io.infinite.pigeon.threads.SenderThread.run(SenderThread.groovy:44)

2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|METHOD EXCEPTION: sendMessage.io.infinite.pigeon.threads.SenderThread(60,5,100,6)
2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|EXCEPTION (additional occurrence):
2019-02-21 15:54:11:494|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|a64aceed-8e4c-4d4b-8030-0c23bc3b3f0d
2019-02-21 15:54:11:494|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|METHOD EXCEPTION: run.io.infinite.pigeon.threads.SenderThread(40,5,50,6)

Usage

BlackBox is hosted in JCenter via Bintray:

Download

Gradle

...
repositories {
    jcenter()
}
...
compile 'io.infinite:blackbox:1.0.20'
...

BlackBox annotation is applicable to Classes, Methods and Constructors:

import io.infinite.blackbox.BlackBox
import io.infinite.carburetor.CarburetorLevel

@BlackBox(level = CarburetorLevel.EXPRESSION)
String foobar(String foo) {
    String bar = "bar"
    String foobar = foo + bar
    return foobar
}

foobar("foo")
Clone this wiki locally
You can’t perform that action at this time.