DeepDive Logging Journey with Spring, Logback and MDC
Today I would like to describe one of the annoying problem of microservice architecure which is called as Logging. Before explaining our new solution LogCave, I have to tell legacy logging system.
We have two types of logging infrastructure. Both of them requires some user specific data to put these on log information such as email, client version, app version, channel, ip-port and etc. For carrying all these data to every services, we have a threadLocal approach. Then log or report log functions, take this data and sent logs to relevant flows.
INFO;2023-12-02 13:27:26;IPHONE;TR;null;oguzderici@test.com;111.258.11.369:1202;;;;;requestURI:/test-log;rdsId:RDS:20231121132724_XYZASDFGHJKL;;113;;ProcessTime=113First one is console logging, custom functions above of Slf4j, take data from threadLocal and prepare log messages. In our both cases log pattern is hard to understand, it combines all threadLocal data and log messages with semicolon “;”. Thus, when you need to search anything from elastic via kibana you have to write message: “related-email” and message: “related-client-version” and so on.
This approach prevents to use power of elasticsearch infrastructure because every search criteria combined in message. As a result of this, there is very log process time to understand which data is following. Also, messages could be taken wrong by newbies. I should give an example for this, imagine, you will pay bills.
- As a logged in user, you can make operation for yourself.
- As a nonlogin user, you can make operation for yourself.
- An another user can make operation for yourself.
All 3 cases can be operated in the same hour. When you want to search log and just write message : “email”, all footprints will be shown. But which one is related to logged in user ? Then you should filter sender IP and process goes on. Elasticsearch process time, log diversion and any other filter you want to apply will take long process. Sounds bad right :(
Anyway, other logging mechanisms is reporting log. Reporting log take data with additional information and send them to database. Additional information are not included on console logging and ReportDTO is used for them. Report log is also on elastic, so we can search it via kibana. However, report logs are sent via Kafka to database with KafkaConnectors. To send every custom report message there is an interface. Like console logging these additonal informations combined with semicolon. Every semicolon represents different database field, so we have to be careful when writing a message.
Ooops, should I count semicolons as uno dos tres, or write a custom function
When we convert our legacy system to microservice architecture, we cannot destroy this infrastructure at the beginning and carry on with this. However, in microservice report logging we did not use kafka connector database approach, so we code reporting service to consume data and write it on database.
In microservice console logging, we had a log library to carry on data as our legacy logging. But in microservices, we have lots of implementation, and carry all common data to microservices in header with interceptors. Still we have lots of boilerplate code and copy paste logic. But we have to demolish it.
After long and several negotiations with operations, QA and data analysts, we started to design logging system from scratch. First we change semicolon appender base approach from microservice logging and take some data outside of message. That means we have new fields on elastic such as email, clientIp, clientVersion, language and etc. As a result of this, we can make explicit search on kibana like email:””, and language:”” … This gives better result and search time. To accomplish that, we make our logback file with related fields.
Then, we need to carry all these common information between microservices. We do not want to use interceptors because lack of implementation can cause wrong log messages. We use micrometer baggages to carry data. All common headers between microservices are carry on baggage fields. With the power of MDC, we put our common headers to console logging with logback file with 0 effort.
While we are using MDC, we need to add some additional fields to facilitate tracking such as requestUri, requestMethod, and operation start time. Herewith, fields are set to MDC when request reach to service.
We are very glad to get rid of console logging old approach. There is no other dependency injection for console logging anymore. We just code log.info(“our message”) and just complete everything.
Lets take care of report logging. Ok we have new fields on elastic for console logging and we carry these with micrometer, first, we need to extract these common fields from ReportDTO. While we are ready to start demolishing report logging, lets make it Json Based. But we still add reportLogger to services as dependency.
After a some searches, we customize our kafka appender to send logs. On logback file we add kafka appender and logback configuration. ReportService static functions are coded to use new kafkaAppender logger on system. We still use Slf4j logger but when we call function, logs are both on console and produce on Kafka.
Extracted DTO is sent on message, so we need to change our reporting service (report consumer service). By using mapper functionaly of mapstruct, we combine appender common headers data and reportDTO to reportEntity.
We can use ReportLogService very easily when we compare with our old fashion logger system. Also, in our some cases, we coded an annotation to simplify report log in business logic or service error exception cases. As a result of this, there is no need to write try catch blocks in business layer.
{
"_index": "OD_digitalchannels-202312",
"_type": "_doc",
"_id": "12121211-db72-ae5a-2125-fgfdghdad",
"_version": 1,
"_score": null,
"_source": {
"@timestamp": "2023-12-12T09:00:03.614Z",
"date_time": "2023-12-12T12:00:03.513+03",
"level": "INFO",
"traceId": "f8b6c1f011046f43",
"spanId": "73a42d369f2c70ef",
"email": "oguzderici@test.com",
"clientIp": "1.1.1.1",
"clientPort": "30",
"request-method": "GET",
"request-uri": "/credit-cards",
"sessionId": "OD:RDS:20231212115321_DEAA48BADCB3323231",
"channel": "NATIVE",
"channelType": "IOS",
"language": "TR",
"appVersion": "18.2.0",
"osVersion": "",
"source": "kafkaLogger:9",
"message": "{\"reportStatus\":\"SUCCESS\",\"categoryType\":\"OD\",\"actionId\":\"credit.card\",\"productId\":\"\",\"failReason\":\"\",\"failReasonCode\":\"\",\"businessFailReason\":\"\",
\"information\":\"Credit cards list operation\",\"catalogId\":\"\",\"customerNo\":\"111111\",\"orderId\":\"DD-27\",\"orderPaymentType\":\"\",\"accountId\":\"125110\",\"duration\":\"3\",\"operator\":\"Turkcell\",\"type\":\"\"}",
"service_name": "dc-payment-service",
"hostname": "dc-payment-service-121-dcx5rdx",
"kube_pod": "dc-payment-service-121-dcx5rdx",
"kube_namespace": "digitalchannels"
},
"fields": {
"date_time": [
"2023-12-12T09:00:03.513Z"
]
},
"highlight": {
"service_name": [
"@kibana-highlighted-field@dc-payment-service@/kibana-highlighted-field@"
],
"source": [
"@kibana-highlighted-field@kafkaLogger:9@/kibana-highlighted-field@"
]
},
"sort": [
1702371603513
]
}To summarize, our logging journey is one of the important milestone because, elasticsearch operations have both accelerated and improved with its understandability and new structure. Also, with easy log functionality, development time has accelerated. Let’s take a break and grab a coffee. Happy coding …
References
