web项目log日志查看分析->流程理解

1.DEBUG [2017-07-10 11:38:41,705][] org.springframework.web.servlet.DispatcherServlet:865 - DispatcherServlet with name 'dispatcherServlet' processing POST request for [/profit/queryProfitAccountList] 
注：spring mvc的的DispatcherServlet dispatcherservlet会日志打印传进来的每个请求的url和http方法，并日志debug输出打印

2.AbstractHandlerMethodMapping dispatcherservlet处理分发请求后，当然就要handlermapping查找controller的方法了，如下打印：

2.DEBUG [2017-07-10 11:38:41,705][] org.springframework.web.servlet.handler.AbstractHandlerMethodMapping:310 - Looking up handler method for path /profit/queryProfitAccountList 
debug打印“Looking up handler method for path /profit/queryProfitAccountList 

3.DEBUG [2017-07-10 11:38:41,705][] org.springframework.web.servlet.handler.AbstractHandlerMethodMapping:317 - Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.pingan.property.icore.pap.aggregation.profit.controller.ProfitController.queryProfitAccounts(com.pingan.property.icore.pap.aggregation.profit.dto.QueryProfitAccountReqDTO)]

AbstractHandlerMethodMapping

handlermapping查找到url对应的controller和方法，并log打印出来controller类名和处理方法名，并打印出整个方法的形参和返回值


4.DEBUG [2017-07-10 11:38:41,706][] org.springframework.beans.factory.support.AbstractBeanFactory:251 - Returning cached instance of singleton bean 'profitController' 

找到controller了（即handler）,那么就从spring ioc里拿出来这个单例的bean呗，就有了AbstractBeanFactory类去取bean。


5.接下来就要调用

AbstractMessageConverterMethodArgumentResolver进行入参的json格式转换了。

将json string转为DTO，
再返回输出的时候将DTO转换为json字符串

DEBUG [2017-07-10 11:38:41,719][] org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver:197 - Read [class com.pingan.property.icore.pap.aggregation.profit.dto.QueryProfitAccountReqDTO] as "application/json;charset=UTF-8" with [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@19200eab] 

6.马上要sql语句操纵的时候，

org.mybatis.spring.SqlSessionUtils

SqlSessionUtils

mybatis会打印创建sqlsession的log

DEBUG [2017-07-10 11:38:41,719][] org.mybatis.spring.SqlSessionUtils:97 - Creating a new SqlSession 

7.然后可以mybatis设置sqlsession是否同步

DEBUG [2017-07-10 11:38:41,719][] org.mybatis.spring.SqlSessionUtils:148 - SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@391b61a4] was not registered for synchronization because synchronization is not active 

8.创建sqlsession后，mybatis就要从

org.springframework.jdbc.datasource.DataSourceUtils

datasource里取出一个jdbc connection了

DEBUG [2017-07-10 11:38:41,720][] org.springframework.jdbc.datasource.DataSourceUtils:110 - Fetching JDBC Connection from DataSource 

9.jdbc connection拿出来后，就要对connection进行事务处理判断了。
spring 默认也会打印出来关于这个connection的数据库连接串信息

DEBUG [2017-07-10 11:38:41,723][] org.mybatis.spring.transaction.SpringManagedTransaction:87 - JDBC Connection [74708194, URL=jdbc:oracle:thin:@t0eshop.dbstg.paic.com.cn:1597:t0eshop, UserName=PAPOPR, Oracle JDBC driver] will not be managed by Spring 

10.spring jdbc connection拿到后，也进行了事务判断，接下来mybatis就要打印sql语句log了。
mybatis负责打印sql语句log的用到的类是org.apache.ibatis.logging.jdbc.BaseJdbcLogger。

DEBUG [2017-07-10 11:38:41,724][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==>  Preparing: SELECT uuid FROM uid_cert_mobile WHERE mobile_no=? AND is_valid = ?  
DEBUG [2017-07-10 11:38:41,724][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==> Parameters: 13565050505(String), Y(String) 
DEBUG [2017-07-10 11:38:41,727][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - <==      Total: 1 

11.sql局域执行完，mybatis打印log显示关闭这条connection

org.mybatis.spring.SqlSessionUtils

DEBUG [2017-07-10 11:38:41,728][] org.mybatis.spring.SqlSessionUtils:191 - Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@391b61a4] 

12.实际mybatis关闭sqlsession是调用spring jdbc的return connection到datsource

org.springframework.jdbc.datasource.DataSourceUtils

DEBUG [2017-07-10 11:38:41,728][] org.springframework.jdbc.datasource.DataSourceUtils:327 - Returning JDBC Connection to DataSource 

13.return完spring的jdbc connection给spring jdbc datasource后，就要统一返回dto转成成json字符串返回了啊。
又要用到spring mvc的

AbstractMessageConverterMethodProcessor。
注意：这里有个区别，一个是read一个是write。
read是在http request进来的时候将json字符串转换为dto并作为参数传给controller。
write是controller返回dto后，将dto转换为json字符串，为write

DEBUG [2017-07-10 11:39:35,135][] org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor:234 - Written [{profitAccountList=[com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@755c5763, com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@a2bfab5, com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@6bc29bbb]}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@19200eab] 

14.既然controller已处理完，且已转换为json,就要返回给dispatcherservlet 给modelandview了

DEBUG [2017-07-10 11:39:35,135][] org.springframework.web.servlet.DispatcherServlet:1044 - Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling 

15.请求处理完后，spring mvc的FrameworkServlet会打印出请求处理完的log语句。
至此，一个request请求完毕

DEBUG [2017-07-10 11:39:35,135][] org.springframework.web.servlet.FrameworkServlet:1000 - Successfully completed request 

完整的log打印如下：

DEBUG [2017-07-10 11:39:30,791][] org.springframework.web.servlet.DispatcherServlet:865 - DispatcherServlet with name 'dispatcherServlet' processing POST request for [/profit/queryProfitAccountList] 
DEBUG [2017-07-10 11:39:30,791][] org.springframework.web.servlet.handler.AbstractHandlerMethodMapping:310 - Looking up handler method for path /profit/queryProfitAccountList 
DEBUG [2017-07-10 11:39:30,791][] org.springframework.web.servlet.handler.AbstractHandlerMethodMapping:317 - Returning handler method [public java.util.Map<java.lang.String, java.lang.Object> com.pingan.property.icore.pap.aggregation.profit.controller.ProfitController.queryProfitAccounts(com.pingan.property.icore.pap.aggregation.profit.dto.QueryProfitAccountReqDTO)] 
DEBUG [2017-07-10 11:39:30,791][] org.springframework.beans.factory.support.AbstractBeanFactory:251 - Returning cached instance of singleton bean 'profitController' 
INFO  [2017-07-10 11:39:30,792][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:46 - *************** EntranceInterceptor preHandle() begin **************** 
INFO  [2017-07-10 11:39:30,793][] com.pingan.property.icore.pap.access.um.controller.UMApiAuthService:36 - pap->properties读取到umpwd is3mxVy95H 
INFO  [2017-07-10 11:39:30,793][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:115 - umAuthUser authorization header is: Basic Vl9QQTAxM19QQTE4X0VNQUxMOjdrSjV0ZkUy 
INFO  [2017-07-10 11:39:30,793][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:118 - umAuthUser decoded namePwd is: V_PA013_PA18_EMALL:7kJ5tfE2 
INFO  [2017-07-10 11:39:30,794][] com.pingan.property.icore.pap.access.um.controller.GuavaCachedService:60 - key : V_PA013_PA18_EMALL:7kJ5tfE2，在缓存中不存在，需要调用外部接口获取值 
INFO  [2017-07-10 11:39:30,794][] com.pingan.property.icore.pap.access.um.controller.GuavaCachedService:65 - userName = V_PA013_PA18_EMALL, passwd = 7kJ5tfE2 
INFO  [2017-07-10 11:39:30,803][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:125 - pap->用户的cookie : 1 
INFO  [2017-07-10 11:39:30,803][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:63 - pap-> um switch->1 
INFO  [2017-07-10 11:39:30,803][] com.pingan.property.icore.pap.access.interceptor.EntranceInterceptor:65 - ************** EntranceInterceptor preHandle() end********************* 
DEBUG [2017-07-10 11:39:30,803][] org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver:197 - Read [class com.pingan.property.icore.pap.aggregation.profit.dto.QueryProfitAccountReqDTO] as "application/json;charset=UTF-8" with [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@19200eab] 
INFO  [2017-07-10 11:39:30,804][] com.pingan.property.icore.pap.aggregation.profit.controller.ProfitController:75 - 查询权益账户信息传入参数:req=QueryProfitAccountReqDTO [mobileNo=13565050505, profitType=null, uuid=null] 
DEBUG [2017-07-10 11:39:30,804][] org.mybatis.spring.SqlSessionUtils:97 - Creating a new SqlSession 
DEBUG [2017-07-10 11:39:30,804][] org.mybatis.spring.SqlSessionUtils:148 - SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@457c4787] was not registered for synchronization because synchronization is not active 
DEBUG [2017-07-10 11:39:30,805][] org.springframework.jdbc.datasource.DataSourceUtils:110 - Fetching JDBC Connection from DataSource 
DEBUG [2017-07-10 11:39:30,808][] org.mybatis.spring.transaction.SpringManagedTransaction:87 - JDBC Connection [1699135185, URL=jdbc:oracle:thin:@t0eshop.dbstg.paic.com.cn:1597:t0eshop, UserName=PAPOPR, Oracle JDBC driver] will not be managed by Spring 
DEBUG [2017-07-10 11:39:30,808][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==>  Preparing: SELECT uuid FROM uid_cert_mobile WHERE mobile_no=? AND is_valid = ?  
DEBUG [2017-07-10 11:39:30,809][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==> Parameters: 13565050505(String), Y(String) 
DEBUG [2017-07-10 11:39:30,812][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - <==      Total: 1 
DEBUG [2017-07-10 11:39:30,813][] org.mybatis.spring.SqlSessionUtils:191 - Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@457c4787] 
DEBUG [2017-07-10 11:39:30,813][] org.springframework.jdbc.datasource.DataSourceUtils:327 - Returning JDBC Connection to DataSource 
INFO  [2017-07-10 11:39:30,813][] com.pingan.property.icore.pap.common.util.PAPLogger:77 - 查询权益账户信息传入参数:req=com.pingan.property.icore.pap.profit.dto.AccountDTO@3cf11332 
INFO  [2017-07-10 11:39:30,813][] com.pingan.property.icore.pap.common.util.PAPLogger:77 - 查询权益账户信息传入参数:req=com.pingan.property.icore.pap.profit.dto.AccountDTO@3cf11332 
DEBUG [2017-07-10 11:39:30,813][] org.mybatis.spring.SqlSessionUtils:97 - Creating a new SqlSession 
DEBUG [2017-07-10 11:39:30,814][] org.mybatis.spring.SqlSessionUtils:148 - SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1a4ea0e6] was not registered for synchronization because synchronization is not active 
DEBUG [2017-07-10 11:39:30,814][] org.springframework.jdbc.datasource.DataSourceUtils:110 - Fetching JDBC Connection from DataSource 
DEBUG [2017-07-10 11:39:30,817][] org.mybatis.spring.transaction.SpringManagedTransaction:87 - JDBC Connection [1026133079, URL=jdbc:oracle:thin:@t0eshop.dbstg.paic.com.cn:1597:t0eshop, UserName=PAPOPR, Oracle JDBC driver] will not be managed by Spring 
DEBUG [2017-07-10 11:39:30,818][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==>  Preparing: select ID_PROFIT_ACCOUNT, UUID, PROFIT_TYPE, AVAILABLE_NUM, HISTORY_NUM, CREATED_DATE, CREATED_BY, UPDATED_DATE, UPDATED_BY, IS_VALID from PROFIT_ACCOUNT where UUID = ? and PROFIT_TYPE = ? and IS_VALID = 'Y'  
DEBUG [2017-07-10 11:39:30,818][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==> Parameters: 52007A8473E72EE6E054000B5DE0B7FC(String), 1(String) 
DEBUG [2017-07-10 11:39:30,822][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - <==      Total: 1 
DEBUG [2017-07-10 11:39:30,822][] org.mybatis.spring.SqlSessionUtils:191 - Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1a4ea0e6] 
DEBUG [2017-07-10 11:39:30,822][] org.springframework.jdbc.datasource.DataSourceUtils:327 - Returning JDBC Connection to DataSource 
INFO  [2017-07-10 11:39:30,822][] com.pingan.property.icore.pap.common.util.PAPLogger:77 - 查询权益账户信息传入参数:req=com.pingan.property.icore.pap.profit.dto.AccountDTO@3cf11332 
DEBUG [2017-07-10 11:39:30,823][] org.mybatis.spring.SqlSessionUtils:97 - Creating a new SqlSession 
DEBUG [2017-07-10 11:39:30,823][] org.mybatis.spring.SqlSessionUtils:148 - SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@6dc91d15] was not registered for synchronization because synchronization is not active 
DEBUG [2017-07-10 11:39:30,823][] org.springframework.jdbc.datasource.DataSourceUtils:110 - Fetching JDBC Connection from DataSource 
DEBUG [2017-07-10 11:39:30,826][] org.mybatis.spring.transaction.SpringManagedTransaction:87 - JDBC Connection [1502997277, URL=jdbc:oracle:thin:@t0eshop.dbstg.paic.com.cn:1597:t0eshop, UserName=PAPOPR, Oracle JDBC driver] will not be managed by Spring 
DEBUG [2017-07-10 11:39:30,827][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==>  Preparing: select ID_PROFIT_ACCOUNT, UUID, PROFIT_TYPE, AVAILABLE_NUM, HISTORY_NUM, CREATED_DATE, CREATED_BY, UPDATED_DATE, UPDATED_BY, IS_VALID from PROFIT_ACCOUNT where UUID = ? and PROFIT_TYPE = ? and IS_VALID = 'Y'  
DEBUG [2017-07-10 11:39:30,827][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==> Parameters: 52007A8473E72EE6E054000B5DE0B7FC(String), 2(String) 
DEBUG [2017-07-10 11:39:30,831][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - <==      Total: 1 
DEBUG [2017-07-10 11:39:30,831][] org.mybatis.spring.SqlSessionUtils:191 - Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@6dc91d15] 
DEBUG [2017-07-10 11:39:30,831][] org.springframework.jdbc.datasource.DataSourceUtils:327 - Returning JDBC Connection to DataSource 
INFO  [2017-07-10 11:39:30,832][] com.pingan.property.icore.pap.common.util.PAPLogger:77 - 查询权益账户信息传入参数:req=com.pingan.property.icore.pap.profit.dto.AccountDTO@3cf11332 
DEBUG [2017-07-10 11:39:30,832][] org.mybatis.spring.SqlSessionUtils:97 - Creating a new SqlSession 
DEBUG [2017-07-10 11:39:30,832][] org.mybatis.spring.SqlSessionUtils:148 - SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@36332959] was not registered for synchronization because synchronization is not active 
DEBUG [2017-07-10 11:39:30,832][] org.springframework.jdbc.datasource.DataSourceUtils:110 - Fetching JDBC Connection from DataSource 
DEBUG [2017-07-10 11:39:30,836][] org.mybatis.spring.transaction.SpringManagedTransaction:87 - JDBC Connection [1200181500, URL=jdbc:oracle:thin:@t0eshop.dbstg.paic.com.cn:1597:t0eshop, UserName=PAPOPR, Oracle JDBC driver] will not be managed by Spring 
DEBUG [2017-07-10 11:39:30,836][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==>  Preparing: select ID_PROFIT_GP_ACCOUNT, UUID, AVAILABLE_NUM, HISTORY_NUM, CREATED_DATE, CREATED_BY, UPDATED_DATE, UPDATED_BY, IS_VALID from PROFIT_GP_ACCOUNT where UUID = ? and IS_VALID = 'Y'  
DEBUG [2017-07-10 11:39:30,836][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - ==> Parameters: 52007A8473E72EE6E054000B5DE0B7FC(String) 
DEBUG [2017-07-10 11:39:30,840][] org.apache.ibatis.logging.jdbc.BaseJdbcLogger:181 - <==      Total: 1 
DEBUG [2017-07-10 11:39:30,840][] org.mybatis.spring.SqlSessionUtils:191 - Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@36332959] 
DEBUG [2017-07-10 11:39:30,841][] org.springframework.jdbc.datasource.DataSourceUtils:327 - Returning JDBC Connection to DataSource 
DEBUG [2017-07-10 11:39:30,841][] org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor:234 - Written [{profitAccountList=[com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@620ddcad, com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@14b61ef2, com.pingan.property.icore.pap.aggregation.profit.dto.ProfitAccountDTO@3b6084dc]}] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@19200eab] 
DEBUG [2017-07-10 11:39:30,842][] org.springframework.web.servlet.DispatcherServlet:1044 - Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling 
DEBUG [2017-07-10 11:39:30,842][] org.springframework.web.servlet.FrameworkServlet:1000 - Successfully completed request