SLF4J你一些不知道的附加功能

缺乏、安全感 2023-01-10 01:24 152阅读 0赞

**目录**

SLF4J extensions

Profilers

Extended Logger

Event Logging

--------------------

# SLF4J extensions #

slf4j官方提供了一些附加功能，这些功能都在*slf4j-ext.jar *中提供，这些附加功能主要包括:

*  Profiler 分析器：可以阶段性的记录日志，并打印出各个阶段所耗费的时间，可用于性能分析之类的；
 *  Extended logger 扩展日志：提供entry和exit方法，可以在方法开始和结束时使用，打印记录使用过扩展日志的方法，以及方法的出入参数；
 *  Event Logger 事件日志：提供异步日志支持，通过MDC进行参数传递，实现异部线程之间日志参数的传递，如记录全局traceId,请求ip等；
 *  Logging added with Java Agent 代理日志添加：支持Java Agent代理做切面日志。

## Profilers ##

*Example: Using the profiler:*

public class BasicProfilerDemo {
     
       public static void main(String[] args) {
         // create a profiler called "BASIC"
         Profiler profiler = new Profiler("BASIC");
         profiler.start("A");
         doA();
     
         profiler.start("B");
         doB();
         
         profiler.start("OTHER");
         doOther();
         profiler.stop().print();
       }
    }

Running the above example will output the following output.

+ Profiler [BASIC]
    |-- elapsed time                      [A]   220.487 milliseconds.
    |-- elapsed time                      [B]  2499.866 milliseconds.
    |-- elapsed time                  [OTHER]  3300.745 milliseconds.
    |-- Total                         [BASIC]  6022.568 milliseconds.

*Example2:* Profiler nesting

public class NestedProfilerDemo {
     
      public static void main(String[] args) {
         // create a profiler called "DEMO"
         Profiler profiler = new Profiler("DEMO");
        
         // register this profiler in the thread context's profiler registry
         ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
         profiler.registerWith(profilerRegistry);
        
         // start a stopwatch called "RANDOM"
         profiler.start("RANDOM");
         RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
         int n = 1000*1000;
         int[] randomArray = riaGenerator.generate(n);
         
         // create and start a nested profiler called "SORT_AND_PRUNE"
         // By virtue of its parent-child relationship with the "DEMO"
         // profiler, and the previous registration of the parent profiler, 
         // this nested profiler will be automatically registered
         // with the thread context's profiler registry
         profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
         
         SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
         pruner.sortAndPruneComposites();
         
         // stop and print the "DEMO" printer
         profiler.stop().print();
       }
    }
    
    public class SortAndPruneComposites {
     
      static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
        
      final int[] originalArray;
      final int originalArrayLength;
       
      public SortAndPruneComposites(int[] randomArray) {
        this.originalArray = randomArray;
        this.originalArrayLength = randomArray.length;
       
      }
       
      public int[] sortAndPruneComposites() {
        // retrieve previously registered profiler named "SORT_AND_PRUNE"
        ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
        Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);
    
        // start a new stopwatch called SORT
        sortProfiler.start("SORT");
        int[] sortedArray = sort();
        // start a new stopwatch called PRUNE_COMPOSITES
        sortProfiler.start("PRUNE_COMPOSITES");
        int result[] = pruneComposites(sortedArray);
        
        return result;
      }
    }

result:

+ Profiler [DEMO]
    |-- elapsed time                 [RANDOM]    70.524 milliseconds.
    |---+ Profiler [SORT_AND_PRUNE]
        |-- elapsed time                   [SORT]   665.281 milliseconds.
        |-- elapsed time       [PRUNE_COMPOSITES]  5695.515 milliseconds.
        |-- Subtotal             [SORT_AND_PRUNE]  6360.866 milliseconds.
    |-- elapsed time         [SORT_AND_PRUNE]  6360.866 milliseconds.
    |-- Total                          [DEMO]  6433.922 milliseconds.

## Extended Logger ##

package com.test;
    
    import org.slf4j.ext.XLogger;
    import org.slf4j.ext.XLoggerFactory;
    
    import java.util.Random;
    
    public class TestService {
      private XLogger logger = XLoggerFactory.getXLogger(TestService.class
          .getName());
    
      private String[] messages = new String[] { "Hello, World",
          "Goodbye Cruel World", "You had me at hello" };
    
      private Random rand = new Random(1);
    
      public String retrieveMessage() {
        logger.entry();
    
        String testMsg = getMessage(getKey());
    
        logger.exit(testMsg);
        return testMsg;
      }
    
      public void exampleException() {
        logger.entry();
        try {
          String msg = messages[messages.length];
          logger.error("An exception should have been thrown");
        } catch (Exception ex) {
          logger.catching(ex);
        }
        logger.exit();
      }
    
      public String getMessage(int key) {
        logger.entry(key);
    
        String value = messages[key];
    
        logger.exit(value);
        return value;
      }
    
      private int getKey() {
        logger.entry();
        int key = rand.nextInt(messages.length);
        logger.exit(key);
        return key;
      }
    }

package com.test;
    
    public class App {
      public static void main( String[] args )    {
        TestService service = new TestService();
        service.retrieveMessage();
        service.retrieveMessage();
        service.exampleException();
      }
    }

xml

<?xml version='1.0' encoding='UTF-8'?>
    <configuration>
      <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
          <level>ERROR</level>
          <onMatch>ACCEPT</onMatch>
          <onMismatch>DENY</onMismatch>
        </filter>
        <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
        </layout>
      </appender>
      <appender name="log" class="ch.qos.logback.core.FileAppender">
        <File>target/test.log</File>
        <Append>false</Append>
        <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
        </layout>
      </appender>
    
      <root>
        <level value="trace" />
        <appender-ref ref="log" />
      </root>
    </configuration>

result:

00:07:57.725 TRACE com.test.TestService:22 retrieveMessage - entry
    00:07:57.738 TRACE com.test.TestService:57 getKey - entry
    00:07:57.739 TRACE com.test.TestService:59 getKey - exit with (0)
    00:07:57.741 TRACE com.test.TestService:47 getMessage - entry with (0)
    00:07:57.741 TRACE com.test.TestService:51 getMessage - exit with (Hello, World)
    00:07:57.742 TRACE com.test.TestService:26 retrieveMessage - exit with (Hello, World)
    00:07:57.742 TRACE com.test.TestService:22 retrieveMessage - entry
    00:07:57.742 TRACE com.test.TestService:57 getKey - entry
    00:07:57.743 TRACE com.test.TestService:59 getKey - exit with (1)
    00:07:57.745 TRACE com.test.TestService:47 getMessage - entry with (1)
    00:07:57.745 TRACE com.test.TestService:51 getMessage - exit with (Goodbye Cruel World)
    00:07:57.746 TRACE com.test.TestService:26 retrieveMessage - exit with (Goodbye Cruel World)
    00:07:57.746 TRACE com.test.TestService:32 exampleException - entry
    00:07:57.750 ERROR com.test.TestService:40 exampleException - catching
    java.lang.ArrayIndexOutOfBoundsException: 3
      at com.test.TestService.exampleException(TestService.java:35)
      at com.test.AppTest.testApp(AppTest.java:39)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:585)
      at junit.framework.TestCase.runTest(TestCase.java:154)
      at junit.framework.TestCase.runBare(TestCase.java:127)
      at junit.framework.TestResult$1.protect(TestResult.java:106)
      at junit.framework.TestResult.runProtected(TestResult.java:124)
      at junit.framework.TestResult.run(TestResult.java:109)
      at junit.framework.TestCase.run(TestCase.java:118)
      at junit.framework.TestSuite.runTest(TestSuite.java:208)
      at junit.framework.TestSuite.run(TestSuite.java:203)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:585)
      at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
      at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
      at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
      at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:585)
      at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
      at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)
    00:07:57.750 TRACE com.test.TestService:42 exampleException - exit

## Event Logging ##

使用EventLogging时MDC中可以填充一些信息，使用 EventLogger.logEvent(data) 可以被记录

下面例子在请求过滤器中将ipAddress,loginId,hostName,productName,locale,timeZone信息都全局存入了MDC中

Appender中日志格式通过%X\{key\}的方式可以打印出对应的值

import org.slf4j.MDC;
    import org.apache.commons.lang.time.DateUtils;
    
    import javax.servlet.Filter;
    import javax.servlet.FilterConfig;
    import javax.servlet.ServletException;
    import javax.servlet.ServletRequest;
    import javax.servlet.ServletResponse;
    import javax.servlet.FilterChain;
    import javax.servlet.http.HttpSession;
    import javax.servlet.http.HttpServletRequest;
    import javax.servlet.http.Cookie;
    import javax.servlet.http.HttpServletResponse;
    import java.io.IOException;
    import java.util.TimeZone;
    
    public class RequestFilter implements Filter
    {
      private FilterConfig filterConfig;
      private static String TZ_NAME = "timezoneOffset";
    
      public void init(FilterConfig filterConfig) throws ServletException {
        this.filterConfig = filterConfig;
      }
    
      /**
       * Sample filter that populates the MDC on every request.
       */
      public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
                           FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest)servletRequest;
        HttpServletResponse response = (HttpServletResponse)servletResponse;
        MDC.put("ipAddress", request.getRemoteAddr());
        HttpSession session = request.getSession(false);
        TimeZone timeZone = null;
        if (session != null) {
          // Something should set this after authentication completes
          String loginId = (String)session.getAttribute("LoginId");
          if (loginId != null) {
            MDC.put("loginId", loginId);
          }
          // This assumes there is some javascript on the user's page to create the cookie.
          if (session.getAttribute(TZ_NAME) == null) {
            if (request.getCookies() != null) {
              for (Cookie cookie : request.getCookies()) {
                if (TZ_NAME.equals(cookie.getName())) {
                  int tzOffsetMinutes = Integer.parseInt(cookie.getValue());
                  timeZone = TimeZone.getTimeZone("GMT");
                  timeZone.setRawOffset((int)(tzOffsetMinutes * DateUtils.MILLIS_PER_MINUTE));
                  request.getSession().setAttribute(TZ_NAME, tzOffsetMinutes);
                  cookie.setMaxAge(0);
                  response.addCookie(cookie);
                }
              }
            }
          }
        }
        MDC.put("hostname", servletRequest.getServerName());
        MDC.put("productName", filterConfig.getInitParameter("ProductName"));
        MDC.put("locale", servletRequest.getLocale().getDisplayName());
        if (timeZone == null) {
          timeZone = TimeZone.getDefault();
        }
        MDC.put("timezone", timeZone.getDisplayName());
        filterChain.doFilter(servletRequest, servletResponse);
        MDC.clear();
      }
    
      public void destroy() {
      }
    }

import org.slf4j.ext.EventData;
    import org.slf4j.ext.EventLogger;
    
    import java.util.Date;
    import java.util.UUID;
    
    public class MyApp {
    
      public String doFundsTransfer(Account toAccount, Account fromAccount, long amount) {
        toAccount.deposit(amount);
        fromAccount.withdraw(amount);
        EventData data = new EventData();
        data.setEventDateTime(new Date());
        data.setEventType("transfer");
        String confirm = UUID.randomUUID().toString();
        data.setEventId(confirm);
        data.put("toAccount", toAccount);
        data.put("fromAccount", fromAccount);
        data.put("amount", amount);
        EventLogger.logEvent(data);
        return confirm;
      }
    }

<configuration>
      <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
        </layout>
      </appender>
    
      <appender name="events" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>%d{HH:mm:ss.SSS} %X - %msg%n</Pattern>
        </layout>
      </appender>
    
      <logger name="EventLogger" additivity="false">
        <level value="INFO"/>
        <appender appender-ref="events"/>
      </logger>
    
      <root level="DEBUG">
        <appender-ref ref="STDOUT" />
      </root>
    
    </configuration>