Eclair - Java Spring declarative logging library / Tinkoff.ru blog

klapatnyuk June 8, 2018 at 16:55

Eclair - Java Spring declarative logging library

There are a lot of questions about the work of services at the stages of development, testing and support, and all of them are at first glance different: “What happened?” , “Was there a request?” , “What is the date format?” , “Why is the service not responding?” , Etc. .d.

A correctly compiled log will be able to answer in detail these and many other questions absolutely autonomously without the participation of developers. In pursuit of such a tempting goal, the Eclair logging library was born, designed to engage in dialogue with all participants in the process without pulling too many blankets.

About the blanket and the features of the solution - below.

What is the problem of logging

If you are not very interested in understanding the premises, you can immediately proceed to the description of our solution .

The application log is its alibi.
Most often, only he can prove the success of the application. There is no state in a microservice; adjacent systems are mobile and finicky. “Repeat”, “recreate”, “double-check” - all this is difficult and / or impossible. The log should be informative enough to answer the question: “What happened?” At any time . The log should be clear to everyone: the developer, the tester, sometimes the analyst, sometimes the administrator, sometimes the first line of support - anything happens.
Microservices are about multithreading.
Requests coming to the service (or data requested by the service) are most often processed by several threads. The log of all threads is usually mixed. Do you want to distinguish between parallel threads and distinguish between "sequential" threads? The same stream is reused for sequential processing of requests, over and over again executing its own logic for different data sets. These "sequential" flows from another plane, but their boundaries should be clear to the reader.
The log should save the original data format.
If in reality services are exchanged by XML, then the corresponding log should store XML. It is not always compact and not always beautiful (but convenient). It’s easier to see success, easier to analyze failure. In some cases, the log can be used to manually play or reprocess the request.
Part of the data in the log requires a special relationship.
Incoming data (requests), outgoing data (answers), requests to third-party systems and responses from them are often required to be stored separately. They are subject to special requirements: by shelf life or reliability. In addition, this data can have an impressive amount compared to a typical log line.
Part of the data is not for the log.
The following should usually be excluded from the regular log: binary data (byte arrays, base64, ..), personal data of clients / partners / other individuals and legal entities. It is always an individual story, but systematic and does not lend itself to manual control.

Why not hands

Take org.slf4j.Logger(to him Logback with Appenders of any suit) and write to the log everything that is required. Entrances to the main methods, exits, if necessary, reflect caught errors, some data. Is this necessary? Yes, but:

The amount of code is growing unreasonably (unusually). At first, this is not very striking, if you log only the most basic (successful support, by the way, with this approach).
Calling the logger with your hands quickly becomes laziness. To staticdeclare a field with a logger is too lazy (well, Lombok can do this for us). We developers are lazy. And we listen to our laziness, this is noble laziness: it is persistently changing the world for the better.
Microservices are not good on all sides. Yes, they are small and pretty, but there is a flip side: there are many! A single application from start to finish is often written by one developer. Legacy does not loom before his eyes. Happy, not burdened with imposed rules, the developer considers it a duty to invent his own log format, his principle and his own rules. Then, brilliantly implements the invention. Each class is different. This is problem? Colossal.
Refactoring will break your log. Even the omnipotent Idea will not save him. Updating the log is as impossible as updating the Javadoc. At the same time, at least Javadoc is read only by developers (no, nobody reads), but the audience of logs is much wider and the development team is not limited.
MDC (Mapped Diagnostic Context) is an integral part of a multi-threaded application. Manual filling of the MDC requires timely cleaning at the end of work in the stream. Otherwise, you risk linking one ThreadLocal- non-related data. Hands and eyes to control this, I dare to say, is impossible.

And this is how we solve these problems in our applications.

What is Eclair and what can it do

Eclair is a tool that simplifies the writing of logged code. It helps to collect the necessary meta-information about the source code, associate it with the data flying in the application in runtime and send it to the usual log repository, while generating a minimum of code.

The main goal is to make the log understandable to all participants in the development process. Therefore, the convenience of writing code, the benefits of Eclair do not end, but only begin.

Eclair logs annotated methods and parameters:

logs the method entry / exit from the method / exceptions / arguments / values returned by the method
filters exceptions to log them specifically to types: only where necessary
varies the "detail" of the log, based on the application settings for the current location: for example, in the most detailed case it prints the values of the arguments (all or some), in the shortest version - only the fact of entering the method
prints data as JSON / XML / in any other format (ready to work with Jackson, JAXB out of the box): understands which format is most preferable for a particular parameter
understands SpEL (Spring Expression Language) for declarative installation and MDC auto-cleaning
writes to N loggers, the "logger" in the understanding of Eclair is a bean in the context that implements the interface EclairLogger: you can specify the logger that should process the annotation by name, by alias, or by default
tells the programmer about some errors in using annotations: for example, Eclair knows that it works on dynamic proxies (with all the attendant features), so it can tell you that the annotation on the privatemethod will never work
accepts meta annotations (as Spring calls them): you can define your annotations for logging, using a few basic annotations - to reduce the code
able to mask “sensitive” data when printing: out of the box XPath-shielding XML
writes a log in the "manual" mode, defines the invoker and "deploys" the arguments that implement Supplier: giving the opportunity to initialize the arguments "lazily"

How to connect Eclair

The source code is published on GitHub under the Apache 2.0 license.

To connect, you need Java 8, Maven, and Spring Boot 1.5+. Artifact hosted by Maven Central Repository:

ru.tinkoffeclair-spring-boot-starter0.8.3

The starter contains a standard implementation EclairLogger, using a logging system initialized by Spring Boot with some verified set of settings.

Examples

Here are some examples of typical library usage. First, a code fragment is given, then the corresponding log, depending on the availability of a certain level of logging. A more complete set of examples can be found on the project Wiki in the Examples section .

Simplest example

The default level is DEBUG.

@Log
void simple() {
}

If level is available	... then the log will be like this
`TRACE DEBUG`	`DEBUG [] r.t.e.e.Example.simple > DEBUG [] r.t.e.e.Example.simple <`
`INFO WARN ERROR`	`-`

Log details depend on the available logging level.

The logging level available in the current location affects the log detail. The lower the available level (ie, the closer to TRACE), the more detailed the log.

@Log(INFO)
boolean verbose(String s, Integer i, Double d) {
    return false;
}

Level	Log
`TRACE DEBUG`	`INFO [] r.t.e.e.Example.verbose > s="s", i=4, d=5.6 INFO [] r.t.e.e.Example.verbose < false`
`INFO`	`INFO [] r.t.e.e.Example.verbose > INFO [] r.t.e.e.Example.verbose <`
`WARN ERROR`	`-`

Fine-tuning exception logging

Types of logged exceptions can be filtered. Selected exceptions and their descendants will be pledged. In this example, it NullPointerExceptionwill be logged at the WARN level, Exceptionat the ERROR level (by default), and Errorwill not be logged at all (because it is Errornot included in the filter of the first annotation @Log.errorand is explicitly excluded from the filter of the second annotation).

@Log.error(level = WARN, ofType = {NullPointerException.class, IndexOutOfBoundsException.class})
@Log.error(exclude = Error.class)
void filterErrors(Throwable throwable) throws Throwable {
    throw throwable;
}
// рассмотрен лог вызовов с разными аргументами
filterErrors(new NullPointerException());
filterErrors(new Exception());
filterErrors(new Error());

Level	Log
`TRACE DEBUG INFO WARN`	`WARN [] r.t.e.e.Example.filterErrors ! java.lang.NullPointerException java.lang.NullPointerException: null at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) .. ERROR [] r.t.e.e.Example.filterErrors ! java.lang.Exception java.lang.Exception: null at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) ..`
`ERROR`	`ERROR [] r.t.e.e.Example.filterErrors ! java.lang.Exception java.lang.Exception: null at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) ..`

Set each parameter separately

@Log.in(INFO)
void parameterLevels(@Log(INFO) Double d,
                     @Log(DEBUG) String s,
                     @Log(TRACE) Integer i) {
}

Level	Log
`TRACE`	`INFO [] r.t.e.e.Example.parameterLevels > d=9.4, s="v", i=7`
`DEBUG`	`INFO [] r.t.e.e.Example.parameterLevels > d=9.4, s="v"`
`INFO`	`INFO [] r.t.e.e.Example.parameterLevels > 9.4`
`WARN ERROR`	`-`

Select and customize printout format

The “printers” responsible for the print format can be configured by pre- and post-processors. In the above example, it is maskJaxb2Printerconfigured so that elements corresponding to the XPath expression "//s"are masked with "********". At the same time, it jacksonPrinterprints Dto“as is.”

@Log.out(printer = "maskJaxb2Printer")
Dto printers(@Log(printer = "maskJaxb2Printer") Dto xml,
             @Log(printer = "jacksonPrinter") Dto json,
             Integer i) {
    return xml;
}

Level	Log
`TRACE DEBUG`	`DEBUG [] r.t.e.e.Example.printers > xml=5******, json={"i":5,"s":"password"} DEBUG [] r.t.e.e.Example.printers < 5******`
`INFO WARN ERROR`	`-`

Multiple loggers in context

The method is logged using several loggers at the same time: the default logger (annotated with @Primary) and the logger auditLogger. You can define several loggers if you want to separate logged events not only by level (TRACE - ERROR), but also send them to different storages. For example, the main logger can write a log to a file on disk using slf4j, or it auditLoggercan write a special data slice to an excellent storage (for example, in Kafka) in its own specific format.

@Log
@Log(logger = "auditLogger")
void twoLoggers() {
}

MDC Management

MDCs set using annotation are automatically deleted after exiting the annotated method. An MDC record value can be calculated dynamically using SpEL. The following are examples: a static string perceived by a constant, evaluating an expression 1 + 1, calling a bean jacksonPrinter, calling a staticmethod randomUUID.
MDCs with an attribute are global = truenot deleted after exiting the method: as you can see, the only record remaining in the MDC until the end of the log is this sum.

@Log
void outer() {
    self.mdc();
}
@Mdc(key = "static", value = "string")
@Mdc(key = "sum", value = "1 + 1", global = true)
@Mdc(key = "beanReference", value = "@jacksonPrinter.print(new ru.tinkoff.eclair.example.Dto())")
@Mdc(key = "staticMethod", value = "T(java.util.UUID).randomUUID()")
@Log
void mdc() {
    self.inner();
}
@Log.in
void inner() {
}

Log when executing the above code:

DEBUG [] r.t.e.e.Example.outer >

DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.mdc >

DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.inner >

DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.mdc <

DEBUG [sum=2] r.t.e.e.Example.outer <

Parameter Based MDC Installation

If you specify the MDC using the annotation on the parameter, then the annotated parameter is available as the root object of the evaluation context. Here "s"is a class field Dtowith a type String.

@Log.in
void mdcByArgument(@Mdc(key = "dto", value = "#this")
                   @Mdc(key = "length", value = "s.length()") Dto dto) {
}

Log when executing the above code:
DEBUG [length=8, dto=Dto{i=12, s='password'}] r.t.e.e.Example.mdcByArgument > dto=Dto{i=12, s='password'}

Manual logging

For "manual" logging, it is enough to implement the implementation ManualLogger. Passed arguments that implement the interface Supplierwill be "expanded" only if necessary.

@Autowired
private ManualLogger logger;
@Log
void manual() {
    logger.info("Eager logging: {}", Math.PI);
    logger.debug("Lazy logging: {}", (Supplier) () -> Math.PI);
}

Level	Log
`TRACE DEBUG`	`DEBUG [] r.t.e.e.Example.manual > INFO [] r.t.e.e.Example.manual - Eager logging: 3.141592653589793 DEBUG [] r.t.e.e.Example.manual - Lazy logging: 3.141592653589793 DEBUG [] r.t.e.e.Example.manual <`
`INFO`	`INFO [] r.t.e.e.Example.manual - Eager logging: 3.141592653589793`
`WARN ERROR`	`-`

What does Eclair not do

Eclair does not know where you will store your logs, for how long and in detail. Eclair does not know how you plan to use your log. Eclair carefully extracts from your application all the information you need and redirects it to the storage you configured.

Example configuration EclairLoggerdirecting the log to a Logback logger with a specific Appender:

@Bean
public EclairLogger eclairLogger() {
    LoggerFacadeFactory factory = loggerName -> {
        ch.qos.logback.classic.LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        ch.qos.logback.classic.Logger logger = context.getLogger(loggerName);
        // Appender appender = ?
        // logger.addAppender(appender);
        return new Slf4JLoggerFacade(logger);
    };
    return new SimpleLogger(factory, LoggingSystem.get(SimpleLogger.class.getClassLoader()));
}

This solution is not for everyone.

Before you start using Eclair as the main tool for logging, you should familiarize yourself with a number of features of this solution. These “features” are due to the fact that Eclair is based on the standard proxy mechanism for Spring.

- The speed of execution of the code wrapped in the next proxy is insignificant, but it will drop. For us, these losses are rarely significant. If the question arises of reducing lead time, there are many effective optimization measures. Refusing a convenient informative log can be considered as one of the measures, but not in the first place.

- StackTrace "bloat" a little more. If you're not used to the long stackTrace of Spring proxies, this can be a nuisance for you. For an equally obvious reason, debugging proxied classes will be difficult.

- Not every class and every method can be proxied : privateit will not be possible to proxy methods, you will need self to log the chain of methods in one bean, you cannot proxy something that is not a bean, etc.

In the end

It is completely clear that this tool, like any other, must be able to be used in order to benefit from it. And this material only superficially illuminates the side in which we decided to move in search of the perfect solution.

Criticism, thoughts, hints, links - I warmly welcome any of your participation in the life of the project! I would be glad if you find Eclair useful for your projects.

Tags:

Eclair - Java Spring declarative logging library / Tinkoff.ru blog