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