There are a lot of questions about the work of services at the stages of development, testing and support, and they all seem different at first glance:
“What happened?” ,
“Was there a request?” ,
“What date format?” ,
“Why does the service not respond?” And t .d
Correctly compiled log will be able to answer these and many other questions completely autonomously without the participation of developers. In the pursuit of such a tempting goal, the Eclair logging library was born, designed to carry on a dialogue with all participants in the process, without pulling too much blanket over it.
On the blanket and features of the solution - on.
What is the problem logging
If you are not very interested in understanding the prerequisites, you can go directly to the description of our solution .
- The application log is his alibi.
Prove the success of the application can, most often, only he. Microservice has no state, adjacent systems are mobile and picky. “Repeat”, “recreate”, “recheck” - all this is difficult and / or impracticable. The log should be informative enough to answer the question: “What happened?” At any time. The log should be clear to everyone: a developer, a tester, sometimes an analyst, sometimes an administrator, sometimes the first line of support - anything happens. - Microservices are about multithread.
Requests coming to the service (or the 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 parallel streams and distinguish "sequential" streams? The same stream is reused for sequential processing of requests, performing its logic over and over again for different data sets. These "sequential" flows from another plane, but their boundaries should be clear for the reader. - The log should keep the original data format.
If, in reality, services are being thrown by XML, then the corresponding log should store XML. It is not always compact and not always beautiful (but comfortable). It's easier to make sure of success, it's easier to analyze failure. In some cases, the log can be used to manually play back or re-process 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. Special requirements are imposed on them: according to the 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 log.
From the regular log should usually be excluded: binary data (arrays of bytes, base64, ..), personal data of clients / partners / other individuals and legal entities. This is always an individual story, but it cannot be systematically controlled manually.
Why not hands
Take
org.slf4j.Logger (Logback with Appender to it for any suit) and write to the log everything you need. Inputs to the main methods, outputs, if necessary, reflect the errors caught, some data. Is this necessary? Yes, but:
- The amount of code unreasonably (unusually) grows. 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 quickly becomes lazy. To declare a
static field with a logger is also lazy (well, Lombok can do this for us). We, the developers, are lazy. And we listen to our laziness, this is a noble laziness: it is persistently changing the world for the better. - Microservices are not good from all sides. Yes, they are small and pretty, but there is a downside: there are a lot of them! A single developer often writes a separate application from start to finish. Before his eyes looms legacy. Happy, not burdened with imposed rules, the developer considers it his duty to invent his own log format, his own 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 all-powerful Idea will not save him. Updating the log is just as impossible as it is impossible to update Javadoc. At the same time, only developers read javadoc (no, no one 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 its timely cleaning at the end of the work in the stream. Otherwise, you risk linking with one
ThreadLocal - unrelated data. Hands and eyes to control it, I dare say, it 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 at runtime and send it to the log repository you are accustomed to, generating at least a minimum of code.
The main goal is to make the log understandable to all participants of the development process. Therefore, the convenience of Eclair does not end with the convenience of writing code, it is just beginning.
Eclair logs annotated methods and parameters:
- logs method input / output method / exceptions / arguments / values returned by the method
- filters exceptions to log them specific to types: only where it is needed
- varies the "detail" of the log, based on the application settings for the current location: for example, in the most detailed case 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 (out of the box is ready to work with Jackson, JAXB): understands which format is most preferable for a particular parameter
- understands SpEL (Spring Expression Language) for declarative installation and auto-cleaning of MDC
- writes in N loggers, “logger” in the meaning 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 the use of annotations: for example, Eclair knows what works on dynamic proxies (with all the attendant features), so it can suggest that the annotation on a
private method will never work - perceives meta annotations (as Spring calls them): you can define your annotations for logging, using a few basic annotations — to shorten the code
- can mask sensitive data when printing: out of the XPath-shielding XML box
- writes a log in the "manual" mode, defines invoker and "expands" the arguments that implement the
Supplier : giving the opportunity to initialize the arguments "lazily"
How to connect Eclair
The source code is published in GitHub under the Apache 2.0 license.
To connect, you need Java 8, Maven and Spring Boot 1.5+. The artifact is located in the Maven Central Repository:
<dependency> <groupId>ru.tinkoff</groupId> <artifactId>eclair-spring-boot-starter</artifactId> <version>0.8.3</version> </dependency>
The starter contains a standard implementation of
EclairLogger , which uses an initialized logging system with a spring boot with some verified set of settings.
Examples
Here are some examples of typical library use. 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.
The simplest example
The default level is DEBUG.
@Log void simple() { }
| If available level | ... then the log will be like this |
|---|
TRACE
DEBUG | DEBUG [] rteeExample.simple >
DEBUG [] rteeExample.simple < |
INFO
WARN
ERROR | - |
Log detail depends on available logging level.
The logging level available in the current location affects the log details. The “lower” the available level (i.e., 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 [] rteeExample.verbose > s="s", i=4, d=5.6
INFO [] rteeExample.verbose < false |
INFO | INFO [] rteeExample.verbose >
INFO [] rteeExample.verbose < |
WARN
ERROR | - |
Fine tuning logging exceptions
Types of logged exceptions can be filtered. Selected exceptions and their descendants will be logged. In this example,
NullPointerException will be logged at the WARN level,
Exception at the ERROR level (by default), and
Error will not be logged at all (because
Error not included in the filter of the first
@Log.error annotation and 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; }
| Level | Log |
|---|
TRACE
DEBUG
INFO
WARN | WARN [] rteeExample.filterErrors ! java.lang.NullPointerException
java.lang.NullPointerException: null
at rteeExampleTest.filterErrors(ExampleTest.java:0)
..
ERROR [] rteeExample.filterErrors ! java.lang.Exception
java.lang.Exception: null
at rteeExampleTest.filterErrors(ExampleTest.java:0)
..
|
ERROR | ERROR [] rteeExample.filterErrors ! java.lang.Exception
java.lang.Exception: null
at rteeExampleTest.filterErrors(ExampleTest.java:0)
.. |
Configure each parameter separately
@Log.in(INFO) void parameterLevels(@Log(INFO) Double d, @Log(DEBUG) String s, @Log(TRACE) Integer i) { }
| Level | Log |
|---|
TRACE | INFO [] rteeExample.parameterLevels > d=9.4, s="v", i=7 |
DEBUG | INFO [] rteeExample.parameterLevels > d=9.4, s="v" |
INFO | INFO [] rteeExample.parameterLevels > 9.4 |
WARN
ERROR | - |
Select and customize the print format
“Printers” responsible for the print format can be configured by pre- and post-processors. In the given example,
maskJaxb2Printer configured so that the elements corresponding to the XPath expression
"//s" are masked with the help of
"********" . At the same time,
jacksonPrinter prints
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 [] rteeExample.printers >
xml=<dto><i>5</i><s>********</s></dto>, json={"i":5,"s":"password"}
DEBUG [] rteeExample.printers <
<dto><i>5</i><s>********</s></dto> |
INFO
WARN
ERROR | - |
Several loggers in context
The method is logged using several loggers at the same time: the default logger (annotated with
@Primary ) and the auditLogger
auditLogger . You can define several loggers if you want to divide logged events not only by levels (TRACE - ERROR), but also send them to different storages. For example, the main logger can write a log to a file to disk using slf4j, and
auditLogger can write a special data slice to an excellent repository (for example, Kafka) in its specific format.
@Log @Log(logger = "auditLogger") void twoLoggers() { }
MDC Management
MDCs set using annotation are automatically deleted after leaving the annotated method. The value of an entry in MDC can be calculated dynamically using SpEL. In the example, the static string perceived by the constant, the calculation of the expression
1 + 1 , the call to the
jacksonPrinter , the
static call of the
randomUUID method are
randomUUID .
MDCs with the
global = true attribute are not deleted after exiting the method: as you can see, the only entry left in the MDC until the end of the log is the
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 [] rteeExample.outer >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] rteeExample.mdc >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] rteeExample.inner >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] rteeExample.mdc <
DEBUG [sum=2] rteeExample.outer <MDC installation based on parameters
If you specify MDC using annotation on a parameter, the annotated parameter is available as the root of the evaluation context. Here
"s" is a
Dto class field of 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'}] rteeExample.mdcByArgument > dto=Dto{i=12, s='password'}Manual logging
For “manual” logging, it is enough to implement the
ManualLogger implementation. Transmitted arguments that implement interface
Supplier will be “deployed” only when 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 [] rteeExample.manual >
INFO [] rteeExample.manual - Eager logging: 3.141592653589793
DEBUG [] rteeExample.manual - Lazy logging: 3.141592653589793
DEBUG [] rteeExample.manual < |
INFO | INFO [] rteeExample.manual - Eager logging: 3.141592653589793 |
WARN
ERROR | - |
What the Eclair doesn't do
Eclair does not know where you will keep your logs, how long and detailed it is. Eclair does not know how you plan to use your log. Eclair gently pulls all the information you need from your application and redirects it to the repository you have configured.
An example of an
EclairLogger configuration that sends a 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);
This solution is not for everyone.
Before you start using Eclair as the main logging tool, you should be familiar with a number of features of this solution. These "features" are due to the fact that the Eclair is based on the standard proxying mechanism for Spring.
- The speed of execution of the code wrapped in the next proxy is insignificant, but it will fall. For us, these losses are rarely significant. If the question arises about reducing the execution time, there are many effective optimization measures. Refusal of a convenient informative log can be considered as one of measures, but not first of all.
- StackTrace "swells up" a little more. If you are not used to long stacktracks from Spring proxies, this can be a nuisance to you. For an equally obvious reason, it is difficult to debug proxied classes.
-
Not every class and not every method can be proxied :
private methods cannot be proxied, for logging the chain of methods in one bean you will need self, you can proxy anything that is not a bean, etc.
At last
It is perfectly clear that this tool, like any other, needs to be able to apply in order to benefit from it. And this material only superficially illuminates the side to which we decided to move in search of the ideal solution.
Criticism, thoughts, hints, links - all your participation in the life of the project, I warmly welcome! I would be glad if you find Eclair useful for your projects.