使用场景
最近有个需求,要把记录sql的日志,与业务的分开.在业务中sql太多,在看日志的时候不方便.
使用
maven依赖
使用spring boot starter 里面包含了logback依赖,这里使用spring-boot-starter-web方便测试
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
配置
logback配置
- 配置多个 appender,然后指定包的范围以及指定文件目录.达到sql与业务日志分开记录的目的
- 具体例子
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!-- 业务日志 -->
<appender name="APP_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日志文件输出的文件名-->
<FileNamePattern>data/log/log.%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日志文件保留天数-->
<MaxHistory>30</MaxHistory>
</rollingPolicy>
<!--<encoder class="com.test.query.feign.rewrite.PatternLayoutEncoderReWrite">-->
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<!--<pattern>%msg</pattern>-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
<!--日志文件最大的大小-->
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
</appender>
<!-- 只记录sql日志 -->
<appender name="SQL_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日志文件输出的文件名-->
<FileNamePattern>data/log/log.sql@.%d{yyyy-MM-dd}.log</FileNamePattern>
<!--<FileNamePattern>C:/logs/log.@build.finalName@.%d{yyyy-MM-dd}.log</FileNamePattern>-->
<!--日志文件保留天数-->
<MaxHistory>30</MaxHistory>
</rollingPolicy>
<!--<encoder class="com.test.query.feign.rewrite.PatternLayoutEncoderReWrite">-->
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<!--<pattern>%msg</pattern>-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
<!--日志文件最大的大小-->
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
</appender>
<!-- 控制台输出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
</appender>
<logger name="jdbc.sqlonly" level="INFO" additivity="false">
<appender-ref ref="STDOUT"/>
<appender-ref ref="SQL_LOG"/>
</logger>
<logger name="jdbc.resultset" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
<appender-ref ref="SQL_LOG"/>
</logger>
<logger name="jdbc.connection" level="OFF" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="jdbc.sqltiming" level="OFF" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="jdbc.audit" level="OFF" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<!--指定业务日志包范围-->
<logger name="com.example" level="INFO" additivity="false">
<appender-ref ref="APP_LOG"/>
<appender-ref ref="STDOUT"/>
</logger>
<logger name="com" level="INFO" additivity="false">
<appender-ref ref="APP_LOG"/>
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org" level="INFO" additivity="false">
<appender-ref ref="APP_LOG"/>
<appender-ref ref="STDOUT"/>
</logger>
<!-- 日志输出级别 -->
<root level="info">
<appender-ref ref="STDOUT"/>
</root>
</configuration>
测试
- 项目启动,在启动时指定
ddl-auto: update,在启动时候就会生成sql语句,并记录到SQL_LOG的appender中.而启动日志等非sql,就会保存到APP_LOG的appender中.
测试结果如下
- 文件
log.2018-08-23.log的日志
2018-08-23 13:35:43.006 [main] INFO c.e.s.boot.logback.SpringExampleLogbackApplication - Starting SpringExampleLogbackApplication on macs-MacBook-Pro.local with PID 9199 (/Users/mac/code/github/spring-boot-example-logback/target/classes started by mac in /Users/mac/code/github/spring-boot-example-logback)
2018-08-23 13:35:43.010 [main] INFO c.e.s.boot.logback.SpringExampleLogbackApplication - No active profile set, falling back to default profiles: default
2018-08-23 13:35:43.094 [main] INFO o.s.b.w.s.c.AnnotationConfigServletWebServerApplicationContext - Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2b0f373b: startup date [Thu Aug 23 13:35:43 CST 2018]; root of context hierarchy
2018-08-23 13:35:43.933 [main] INFO o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$92080d45] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-08-23 13:35:44.297 [main] INFO o.s.boot.web.embedded.tomcat.TomcatWebServer - Tomcat initialized with port(s): 8080 (http)
2018-08-23 13:35:44.308 [main] INFO org.apache.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-8080"]
2018-08-23 13:35:44.332 [main] INFO org.apache.catalina.core.StandardService - Starting service [Tomcat]
2018-08-23 13:35:44.332 [main] INFO org.apache.catalina.core.StandardEngine - Starting Servlet Engine: Apache Tomcat/8.5.32
2018-08-23 13:35:44.337 [localhost-startStop-1] INFO org.apache.catalina.core.AprLifecycleListener - The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/Users/mac/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:.]
2018-08-23 13:35:44.407 [localhost-startStop-1] INFO o.a.c.c.C.[.[.[/spring-boot-example-logback] - Initializing Spring embedded WebApplicationContext
2018-08-23 13:35:44.407 [localhost-startStop-1] INFO org.springframework.web.context.ContextLoader - Root WebApplicationContext: initialization completed in 1313 ms
2018-08-23 13:35:44.465 [localhost-startStop-1] INFO o.s.boot.web.servlet.ServletRegistrationBean - Servlet dispatcherServlet mapped to [/]
2018-08-23 13:35:44.469 [localhost-startStop-1] INFO o.s.boot.web.servlet.FilterRegistrationBean - Mapping filter: 'characterEncodingFilter' to: [/*]
2018-08-23 13:35:44.470 [localhost-startStop-1] INFO o.s.boot.web.servlet.FilterRegistrationBean - Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2018-08-23 13:35:44.470 [localhost-startStop-1] INFO o.s.boot.web.servlet.FilterRegistrationBean - Mapping filter: 'httpPutFormContentFilter' to: [/*]
2018-08-23 13:35:44.470 [localhost-startStop-1] INFO o.s.boot.web.servlet.FilterRegistrationBean - Mapping filter: 'requestContextFilter' to: [/*]
2018-08-23 13:35:44.616 [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2018-08-23 13:35:44.687 [main] INFO com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Driver does not support get/set network timeout for connections. (net.sf.log4jdbc.ConnectionSpy.getNetworkTimeout()I)
2018-08-23 13:35:44.756 [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2018-08-23 13:35:44.796 [main] INFO o.s.orm.jpa.LocalContainerEntityManagerFactoryBean - Building JPA container EntityManagerFactory for persistence unit 'default'
2018-08-23 13:35:44.806 [main] INFO org.hibernate.jpa.internal.util.LogHelper - HHH000204: Processing PersistenceUnitInfo [
name: default
...]
2018-08-23 13:35:44.868 [main] INFO org.hibernate.Version - HHH000412: Hibernate Core {5.2.17.Final}
2018-08-23 13:35:44.869 [main] INFO org.hibernate.cfg.Environment - HHH000206: hibernate.properties not found
2018-08-23 13:35:44.904 [main] INFO org.hibernate.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.0.1.Final}
2018-08-23 13:35:45.000 [main] INFO org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
2018-08-23 13:35:45.479 [main] INFO o.s.orm.jpa.LocalContainerEntityManagerFactoryBean - Initialized JPA EntityManagerFactory for persistence unit 'default'
2018-08-23 13:35:45.841 [main] INFO o.s.web.servlet.handler.SimpleUrlHandlerMapping - Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-23 13:35:46.069 [main] INFO o.s.w.s.m.m.a.RequestMappingHandlerAdapter - Looking for @ControllerAdvice: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2b0f373b: startup date [Thu Aug 23 13:35:43 CST 2018]; root of context hierarchy
2018-08-23 13:35:46.102 [main] WARN o.s.b.a.o.j.JpaBaseConfiguration$JpaWebConfiguration$JpaWebMvcConfiguration - spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2018-08-23 13:35:46.137 [main] INFO o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/user/{id}],methods=[GET]}" onto public org.springframework.http.ResponseEntity com.example.spring.boot.logback.controller.UserController.user(java.lang.Long)
2018-08-23 13:35:46.141 [main] INFO o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-08-23 13:35:46.141 [main] INFO o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-08-23 13:35:46.170 [main] INFO o.s.web.servlet.handler.SimpleUrlHandlerMapping - Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-23 13:35:46.170 [main] INFO o.s.web.servlet.handler.SimpleUrlHandlerMapping - Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-08-23 13:35:46.454 [main] INFO o.s.jmx.export.annotation.AnnotationMBeanExporter - Registering beans for JMX exposure on startup
2018-08-23 13:35:46.456 [main] INFO o.s.jmx.export.annotation.AnnotationMBeanExporter - Bean with name 'dataSource' has been autodetected for JMX exposure
2018-08-23 13:35:46.461 [main] INFO o.s.jmx.export.annotation.AnnotationMBeanExporter - Located MBean 'dataSource': registering with JMX server as MBean [com.zaxxer.hikari:name=dataSource,type=HikariDataSource]
2018-08-23 13:35:46.471 [main] INFO org.apache.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-8080"]
2018-08-23 13:35:46.494 [main] INFO org.apache.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2018-08-23 13:35:46.505 [main] INFO o.s.boot.web.embedded.tomcat.TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path '/spring-boot-example-logback'
2018-08-23 13:35:46.509 [main] INFO c.e.s.boot.logback.SpringExampleLogbackApplication - Started SpringExampleLogbackApplication in 4.017 seconds (JVM running for 4.75)
2018-08-23 13:36:12.719 [http-nio-8080-exec-1] INFO o.a.c.c.C.[.[.[/spring-boot-example-logback] - Initializing Spring FrameworkServlet 'dispatcherServlet'
2018-08-23 13:36:12.719 [http-nio-8080-exec-1] INFO org.springframework.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started
2018-08-23 13:36:12.737 [http-nio-8080-exec-1] INFO org.springframework.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 18 ms
2018-08-23 13:36:12.769 [http-nio-8080-exec-1] INFO c.e.spring.boot.logback.controller.UserController - user 1
2018-08-23 13:36:12.968 [http-nio-8080-exec-2] INFO c.e.spring.boot.logback.controller.UserController - user 1
2018-08-23 13:46:16.180 [Thread-12] INFO o.s.b.w.s.c.AnnotationConfigServletWebServerApplicationContext - Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@2b0f373b: startup date [Thu Aug 23 13:35:43 CST 2018]; root of context hierarchy
2018-08-23 13:46:16.185 [Thread-12] INFO o.s.jmx.export.annotation.AnnotationMBeanExporter - Unregistering JMX-exposed beans on shutdown
2018-08-23 13:46:16.185 [Thread-12] INFO o.s.jmx.export.annotation.AnnotationMBeanExporter - Unregistering JMX-exposed beans
2018-08-23 13:46:16.186 [Thread-12] INFO o.s.orm.jpa.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'default'
2018-08-23 13:46:16.187 [Thread-12] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
2018-08-23 13:46:16.189 [Thread-12] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
- 文件
log.sql@.2018-08-23.log的日志
2018-08-23 13:35:45.417 [main] INFO jdbc.sqlonly - select SEQUENCE_CATALOG, SEQUENCE_SCHEMA, SEQUENCE_NAME, INCREMENT from information_schema.sequences
2018-08-23 13:35:45.470 [main] INFO jdbc.sqlonly - create table user_entity (id bigint not null, user_name varchar(255), primary key (id))
2018-08-23 13:36:12.801 [http-nio-8080-exec-1] INFO jdbc.sqlonly - select userentity0_.id as id1_0_0_, userentity0_.user_name as user_nam2_0_0_ from user_entity
userentity0_ where userentity0_.id=1
2018-08-23 13:36:12.969 [http-nio-8080-exec-2] INFO jdbc.sqlonly - select userentity0_.id as id1_0_0_, userentity0_.user_name as user_nam2_0_0_ from user_entity
userentity0_ where userentity0_.id=1
最后发现sql与启动业务日志分离,测试成功
