Peningkatan Java Logging dengan Mapped Diagnostic Context (MDC)

1. Ikhtisar

Pada artikel ini, kita akan mempelajari penggunaan Mapped Diagnostic Context (MDC) untuk meningkatkan pencatatan aplikasi.

Ide dasar dari Mapped Diagnostic Context adalah untuk menyediakan cara untuk memperkaya pesan log dengan potongan informasi yang mungkin tidak tersedia dalam lingkup di mana logging sebenarnya terjadi, tapi itu memang bisa berguna untuk melacak eksekusi program dengan lebih baik.

2. Mengapa Menggunakan MDC

Mari kita mulai dengan sebuah contoh. Misalkan kita harus membuat perangkat lunak yang mentransfer uang. Kami menyiapkan kelas Transfer untuk mewakili beberapa informasi dasar: ID transfer unik dan nama pengirim:

public class Transfer { private String transactionId; private String sender; private Long amount; public Transfer(String transactionId, String sender, long amount) { this.transactionId = transactionId; this.sender = sender; this.amount = amount; } public String getSender() { return sender; } public String getTransactionId() { return transactionId; } public Long getAmount() { return amount; } } 

Untuk melakukan transfer, kita perlu menggunakan layanan yang didukung oleh API sederhana:

public abstract class TransferService { public boolean transfer(long amount) { // connects to the remote service to actually transfer money } abstract protected void beforeTransfer(long amount); abstract protected void afterTransfer(long amount, boolean outcome); } 

Metode beforeTransfer () dan afterTransfer () dapat diganti untuk menjalankan kode kustom tepat sebelum dan tepat setelah transfer selesai.

Kami akan memanfaatkan beforeTransfer () dan afterTransfer () untuk mencatat beberapa informasi tentang transfer .

Mari buat implementasi layanan:

import org.apache.log4j.Logger; import com.baeldung.mdc.TransferService; public class Log4JTransferService extends TransferService { private Logger logger = Logger.getLogger(Log4JTransferService.class); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer " + amount + "$."); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info( "Has transfer of " + amount + "$ completed successfully ? " + outcome + "."); } } 

Masalah utama yang perlu diperhatikan di sini adalah bahwa ketika pesan log dibuat, tidak mungkin untuk mengakses objek Transfer - hanya jumlahnya yang dapat diakses, sehingga tidak mungkin untuk mencatat baik id transaksi atau pengirim.

Mari kita siapkan file log4j.properties biasa untuk masuk ke konsol:

log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout log4j.appender.consoleAppender.layout.ConversionPattern=%-4r [%t] %5p %c %x - %m%n log4j.rootLogger = TRACE, consoleAppender 

Akhirnya, mari kita siapkan aplikasi kecil yang dapat menjalankan banyak transfer pada waktu yang sama melalui ExecutorService :

public class TransferDemo { public static void main(String[] args) { ExecutorService executor = Executors.newFixedThreadPool(3); TransactionFactory transactionFactory = new TransactionFactory(); for (int i = 0; i < 10; i++) { Transfer tx = transactionFactory.newInstance(); Runnable task = new Log4JRunnable(tx); executor.submit(task); } executor.shutdown(); } }

Kami mencatat bahwa untuk menggunakan ExecutorService , kami perlu menggabungkan eksekusi Log4JTransferService dalam adaptor karena executor.submit () mengharapkan Runnable :

public class Log4JRunnable implements Runnable { private Transfer tx; public Log4JRunnable(Transfer tx) { this.tx = tx; } public void run() { log4jBusinessService.transfer(tx.getAmount()); } } 

Ketika kami menjalankan aplikasi demo kami yang mengelola beberapa transfer pada saat yang sama, kami dengan sangat cepat menemukan bahwa log tidak berguna seperti yang kami inginkan . Sulit untuk melacak pelaksanaan setiap transfer karena satu-satunya informasi berguna yang dicatat adalah jumlah uang yang ditransfer dan nama utas yang menjalankan transfer tersebut.

Terlebih lagi, tidak mungkin untuk membedakan antara dua transaksi berbeda dengan jumlah yang sama yang dieksekusi oleh utas yang sama karena baris log terkait pada dasarnya terlihat sama:

... 519 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1393$. 911 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1065$ completed successfully ? true. 911 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1189$. 989 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1350$ completed successfully ? true. 989 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 1178$. 1245 [pool-1-thread-3] INFO Log4JBusinessService - Has transfer of 1393$ completed successfully ? true. 1246 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1133$. 1507 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1189$ completed successfully ? true. 1508 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1907$. 1639 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1178$ completed successfully ? true. 1640 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 674$. ... 

Untungnya, MDC bisa membantu.

3. MDC di Log4j

Mari perkenalkan MDC .

MDC di Log4j memungkinkan kita untuk mengisi struktur seperti peta dengan potongan informasi yang dapat diakses oleh appender ketika pesan log benar-benar ditulis.

Struktur MDC terpasang secara internal ke utas pelaksana dengan cara yang sama seperti variabel ThreadLocal .

Jadi, gagasan tingkat tinggi adalah:

  1. untuk mengisi MDC dengan potongan informasi yang kami ingin sediakan untuk appender
  2. lalu catat pesan
  3. dan terakhir, bersihkan MDC

Pola appender harus diubah secara jelas untuk mendapatkan kembali variabel yang disimpan di MDC.

Jadi mari kita ubah kode sesuai dengan pedoman berikut:

import org.apache.log4j.MDC; public class Log4JRunnable implements Runnable { private Transfer tx; private static Log4JTransferService log4jBusinessService = new Log4JTransferService(); public Log4JRunnable(Transfer tx) { this.tx = tx; } public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getSender()); log4jBusinessService.transfer(tx.getAmount()); MDC.clear(); } } 

Tidak mengherankan MDC.put () digunakan untuk menambahkan kunci dan nilai yang sesuai di MDC sementara MDC.clear () mengosongkan MDC.

Sekarang mari kita ubah properti log4j.properties untuk mencetak informasi yang baru saja kita simpan di MDC. Cukup mengubah pola konversi, dengan menggunakan % X {} placeholder untuk setiap entri yang terdapat dalam MDC yang ingin kami catat:

log4j.appender.consoleAppender.layout.ConversionPattern= %-4r [%t] %5p %c{1} %x - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n

Sekarang, jika kita menjalankan aplikasi, kita akan melihat bahwa setiap baris juga membawa informasi tentang transaksi yang sedang diproses sehingga memudahkan kita untuk melacak eksekusi aplikasi:

638 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1104$ completed successfully ? true. - tx.id=2 tx.owner=Marc 638 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1685$. - tx.id=4 tx.owner=John 666 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1985$ completed successfully ? true. - tx.id=1 tx.owner=Marc 666 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 958$. - tx.id=5 tx.owner=Susan 739 [pool-1-thread-3] INFO Log4JBusinessService - Has transfer of 783$ completed successfully ? true. - tx.id=3 tx.owner=Samantha 739 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1024$. - tx.id=6 tx.owner=John 1259 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1685$ completed successfully ? false. - tx.id=4 tx.owner=John 1260 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1667$. - tx.id=7 tx.owner=Marc 

4. MDC di Log4j2

Fitur yang sama juga tersedia di Log4j2, jadi mari kita lihat cara menggunakannya.

Pertama-tama, siapkan subclass TransferService yang mencatat menggunakan Log4j2:

import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; public class Log4J2TransferService extends TransferService { private static final Logger logger = LogManager.getLogger(); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer {}$.", amount); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome); } } 

Mari kita ubah kode yang menggunakan MDC, yang sebenarnya disebut ThreadContext di Log4j2:

import org.apache.log4j.MDC; public class Log4J2Runnable implements Runnable { private final Transaction tx; private Log4J2BusinessService log4j2BusinessService = new Log4J2BusinessService(); public Log4J2Runnable(Transaction tx) { this.tx = tx; } public void run() { ThreadContext.put("transaction.id", tx.getTransactionId()); ThreadContext.put("transaction.owner", tx.getOwner()); log4j2BusinessService.transfer(tx.getAmount()); ThreadContext.clearAll(); } } 

Sekali lagi, ThreadContext.put () menambahkan entri di MDC dan ThreadContext.clearAll () menghapus semua entri yang ada.

Kami masih kehilangan file log4j2.xml untuk mengkonfigurasi logging. Seperti yang bisa kita catat, sintaks untuk menentukan entri MDC mana yang harus dicatat sama dengan yang digunakan di Log4j:

Sekali lagi, mari jalankan aplikasi dan kita akan melihat informasi MDC dicetak di log:

1119 [pool-1-thread-3] INFO Log4J2BusinessService - Has transfer of 1198$ completed successfully ? true. - tx.id=3 tx.owner=Samantha 1120 [pool-1-thread-3] INFO Log4J2BusinessService - Preparing to transfer 1723$. - tx.id=5 tx.owner=Samantha 1170 [pool-1-thread-2] INFO Log4J2BusinessService - Has transfer of 701$ completed successfully ? true. - tx.id=2 tx.owner=Susan 1171 [pool-1-thread-2] INFO Log4J2BusinessService - Preparing to transfer 1108$. - tx.id=6 tx.owner=Susan 1794 [pool-1-thread-1] INFO Log4J2BusinessService - Has transfer of 645$ completed successfully ? true. - tx.id=4 tx.owner=Susan 

5. MDC di SLF4J / Logback

MDC juga tersedia di SLF4J, dengan syarat didukung oleh pustaka logging yang mendasarinya.

Baik Logback dan Log4j mendukung MDC seperti yang baru saja kita lihat, jadi kita tidak memerlukan hal khusus untuk menggunakannya dengan penyetelan standar.

Let's prepare the usual TransferService subclass, this time using the Simple Logging Facade for Java:

import org.slf4j.Logger; import org.slf4j.LoggerFactory; final class Slf4TransferService extends TransferService { private static final Logger logger = LoggerFactory.getLogger(Slf4TransferService.class); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer {}$.", amount); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome); } } 

Let's now use the SLF4J's flavor of MDC. In this case, the syntax and semantics are the same as that in log4j:

import org.slf4j.MDC; public class Slf4jRunnable implements Runnable { private final Transaction tx; public Slf4jRunnable(Transaction tx) { this.tx = tx; } public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getOwner()); new Slf4TransferService().transfer(tx.getAmount()); MDC.clear(); } } 

We have to provide the Logback configuration file, logback.xml:

   %-4r [%t] %5p %c{1} - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n       

Again, we'll see that the information in the MDC is properly added to the logged messages, even though this information is not explicitly provided in the log.info() method:

1020 [pool-1-thread-3] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1869$ completed successfully ? true. - tx.id=3 tx.owner=John 1021 [pool-1-thread-3] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 1303$. - tx.id=6 tx.owner=Samantha 1221 [pool-1-thread-1] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1498$ completed successfully ? true. - tx.id=4 tx.owner=Marc 1221 [pool-1-thread-1] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 1528$. - tx.id=7 tx.owner=Samantha 1492 [pool-1-thread-2] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1110$ completed successfully ? true. - tx.id=5 tx.owner=Samantha 1493 [pool-1-thread-2] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 644$. - tx.id=8 tx.owner=John

It is worth noting that in case we set up the SLF4J back-end to a logging system that does not support MDC, all the related invocations will be simply skipped without side effects.

6. MDC and Thread Pools

MDC implementations are usually using ThreadLocals to store the contextual information. That's an easy and reasonable way to achieve thread-safety. However, we should be careful using MDC with thread pools.

Let's see how the combination of ThreadLocal-based MDCs and thread pools can be dangerous:

  1. We get a thread from the thread pool.
  2. Then we store some contextual information in MDC using MDC.put() or ThreadContext.put().
  3. We use this information in some logs and somehow we forgot to clear the MDC context.
  4. The borrowed thread comes back to the thread pool.
  5. After a while, the application gets the same thread from the pool.
  6. Since we didn't clean up the MDC last time, this thread still owns some data from the previous execution.

This may cause some unexpected inconsistencies between executions. One way to prevent this is to always remember to clean up the MDC context at the end of each execution. This approach usually needs rigorous human supervision and, therefore, is error-prone.

Another approach is to use ThreadPoolExecutor hooks and perform necessary cleanups after each execution. To do that, we can extend the ThreadPoolExecutor class and override the afterExecute() hook:

public class MdcAwareThreadPoolExecutor extends ThreadPoolExecutor { public MdcAwareThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue workQueue, ThreadFactory threadFactory, RejectedExecutionHandler handler) { super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler); } @Override protected void afterExecute(Runnable r, Throwable t) { System.out.println("Cleaning the MDC context"); MDC.clear(); org.apache.log4j.MDC.clear(); ThreadContext.clearAll(); } }

This way, the MDC cleanup would happen after each normal or exceptional execution automatically. So, there is no need to do it manually:

@Override public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getSender()); new Slf4TransferService().transfer(tx.getAmount()); }

Sekarang kita dapat menulis ulang demo yang sama dengan implementasi eksekutor baru kita:

ExecutorService executor = new MdcAwareThreadPoolExecutor(3, 3, 0, MINUTES, new LinkedBlockingQueue(), Thread::new, new AbortPolicy()); TransactionFactory transactionFactory = new TransactionFactory(); for (int i = 0; i < 10; i++) { Transfer tx = transactionFactory.newInstance(); Runnable task = new Slf4jRunnable(tx); executor.submit(task); } executor.shutdown();

7. Kesimpulan

MDC memiliki banyak aplikasi, terutama dalam skenario di mana eksekusi beberapa utas berbeda menyebabkan pesan log berselang-seling yang sebaliknya akan sulit dibaca.

Dan seperti yang telah kita lihat, ini didukung oleh tiga kerangka kerja logging yang paling banyak digunakan di Java.

Seperti biasa, Anda akan menemukan sumbernya di GitHub.