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