{"id":30216,"date":"2015-11-24T15:29:48","date_gmt":"2015-11-24T09:59:48","guid":{"rendered":"http:\/\/www.tothenew.com\/blog\/?p=30216"},"modified":"2015-11-24T15:29:48","modified_gmt":"2015-11-24T09:59:48","slug":"structured-logging-in-logback-using-mdc","status":"publish","type":"post","link":"https:\/\/www.tothenew.com\/blog\/structured-logging-in-logback-using-mdc\/","title":{"rendered":"Structured logging in logback using MDC"},"content":{"rendered":"<h2 style=\"text-align: center\">General Use Case<\/h2>\n<p>When any application fails in production\u00a0then it is necessary\u00a0is to track how the execution went. For this the standard approach is to add logs. Logs can be helpful in tracking how the execution went but tracking the execution becomes more difficult\u00a0in multithreaded applications. The logs start to get jumbled for various threads. We can obviously start naming our threads and add the thread names in the logs but sometimes we need more information for tracking our business logic.<\/p>\n<h2 style=\"text-align: center\">An Example<\/h2>\n<p>A simple example would be\u00a0a web application. Suppose\u00a0in an e-commerce application User &#8220;Rohan&#8221; is browsing the product &#8220;Shampoo&#8221;. Then a error occurs and we find that Rohan was browsing Shampoo. Now to understand how execution went we need to find all logs for when Rohan was browsing shampoo. The question is how do we proceed with finding all the logs?<\/p>\n<h2 style=\"text-align: center\">Ad hoc solution<\/h2>\n<p>When this error occurs sometimes we realize that our logs don&#8217;t enough\u00a0information to filter out\u00a0all the logs for the situation easily so we go to our code and add<\/p>\n<p>[code]<br \/>\nlog.info(&quot;Username &quot; + username + &quot;,product &quot; + product + &quot; &lt;REST OF LOG&gt;&quot; );<br \/>\n[\/code]<\/p>\n<p>Then we run again and notice that someone missed one log so we need to add this to that log.info or log.debug. Also in future whenever\u00a0we add new log we need to remember to add this information to that log also. It becomes tedious and error-prone.<\/p>\n<h2 style=\"text-align: center\">Better Solution &#8211; MDC<\/h2>\n<p>We can use <a href=\"http:\/\/logback.qos.ch\/manual\/mdc.html\">MDC<\/a>\u00a0to solve this problem. This\u00a0provides us with the ability to add this key value pair\u00a0information to whole blocks of code.<\/p>\n<p>An example application is present\u00a0on <a href=\"https:\/\/github.com\/anshbansal\/examples\/tree\/master\/logExample\">github<\/a>\u00a0if you want a simple running application faster.<\/p>\n<p>We can have classes like below<\/p>\n<p>[code]<br \/>\npublic class Log {<\/p>\n<p>    private static Logger logger = LoggerFactory.getLogger(Log.class);<\/p>\n<p>    public static void main(String[] args) {<br \/>\n        try {<br \/>\n            MDC.put(&quot;username&quot;, &quot;Rohan&quot;);<br \/>\n            logger.debug(&quot;Rohan logs in&quot;);<br \/>\n            new Log2().main();<br \/>\n        } finally {<br \/>\n            MDC.remove(&quot;username&quot;);<br \/>\n        }<br \/>\n    }<\/p>\n<p>}<\/p>\n<p>public class Log2 {<\/p>\n<p>    Logger logger = LoggerFactory.getLogger(Log2.class);<\/p>\n<p>    public void main() {<br \/>\n        try {<br \/>\n            MDC.put(&quot;product&quot;, &quot;Shampoo&quot;);<br \/>\n            logger.info(&quot;staring at the screen&quot;);<\/p>\n<p>        } finally {<br \/>\n            MDC.remove(&quot;product&quot;);<br \/>\n        }<br \/>\n        logger.info(&quot;browsing done&quot;);<br \/>\n    }<\/p>\n<p>}<\/p>\n<p>[\/code]<\/p>\n<p>When we are starting a new block we use MDC.put to put the key value pair\u00a0for the log to use from that point onwards. And in finally block we remove the key from MDC.<\/p>\n<p>The key-value remains for all logs in the current thread. We can create another class and we will get the key value pair in our logs there also as long as the thread remains the same.<\/p>\n<p>A sample run of the above can produce something like this<\/p>\n<p>[code]<br \/>\n14:33:49.127 [username=Rohan] [main] DEBUG dummy.Log &#8211; Rohan logs in<br \/>\n14:33:49.129 [product=Shampoo, username=Rohan] [main] INFO  dummy.Log2 &#8211; staring at the screen<br \/>\n14:33:49.129 [username=Rohan] [main] INFO  dummy.Log2 &#8211; browsing done<br \/>\n[\/code]<\/p>\n<p>When a user logs in (in Log class) we put\u00a0the username in MDC. So as long as the user is logged in all logs will have the user&#8217;s name like in the above example have username=Rohan as long as the application is running. Then when we go to some\u00a0other functionality we can put another key-value pair for\u00a0filtering those particular logs. In the above example we place product=Shampoo in the logs.<\/p>\n<p>So we can\u00a0filter all logs for Rohan or all logs when he was browsing Shampoo. And this is much cleaner approach then appending the information in the logs one-by-one.<\/p>\n<p>But how\u00a0do we decide how this information will be shown in the logs. Like all logging solutions we have a format string which we can use for this.<\/p>\n<p>For the current situation we are using logback\u00a0for our logging so we have the information in our example with the format<\/p>\n<p>[code]<br \/>\n&lt;pattern&gt;%d{HH:mm:ss.SSS} [%X] [%thread] %-5level %logger{36} &#8211; %msg%n&lt;\/pattern&gt;<br \/>\n[\/code]<\/p>\n<p>Here the main part is %X. This gives us the map present in MDC.<\/p>\n<p>MDC has helped us\u00a0a lot when a lot of devs are\u00a0working on QA environment and someone needs to test an API. The logs are running and we need to find how a particular API is working.\u00a0We have been using MDC so we can filter out separate logs via the request ID.<\/p>\n<p>Hope this helps.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>General Use Case When any application fails in production\u00a0then it is necessary\u00a0is to track how the execution went. For this the standard approach is to add logs. Logs can be helpful in tracking how the execution went but tracking the execution becomes more difficult\u00a0in multithreaded applications. The logs start to get jumbled for various threads. [&hellip;]<\/p>\n","protected":false},"author":161,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"iawp_total_views":194},"categories":[446,1],"tags":[528,471,2785,2786,2787],"aioseo_notices":[],"_links":{"self":[{"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/posts\/30216"}],"collection":[{"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/users\/161"}],"replies":[{"embeddable":true,"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/comments?post=30216"}],"version-history":[{"count":0,"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/posts\/30216\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/media?parent=30216"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/categories?post=30216"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.tothenew.com\/blog\/wp-json\/wp\/v2\/tags?post=30216"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}