service方法中的事务传播属性都设为要求新建事务，spring事务管理切面拦截器的order设为1，而log拦截器的order设为2，这意味着这两个要同时执行时，先执行事务拦截器，后执行log拦截器，由于事务管理是一个环绕通知（around），实际上是log拦截器被包围在事务管理拦截器中。
一个不正确的用户登录时，打印的日志：
03:35:16,562 DEBUG OpenSessionInViewFilter:253 - Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
03:35:16,562 DEBUG OpenSessionInViewFilter:196 - Opening single Hibernate Session in OpenSessionInViewFilter
03:35:16,562 DEBUG SessionFactoryUtils:333 - Opening Hibernate Session
03:35:16,562 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] to thread [http-8088-Processor25]
03:35:16,562 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,562 DEBUG HibernateTransactionManager:390 - Found thread-bound Session [org.hibernate.impl.SessionImpl@dfbabd] for Hibernate transaction
03:35:16,578 DEBUG HibernateTransactionManager:292 - Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@5cd7f9]
03:35:16,578 DEBUG HibernateTransactionManager:320 - Creating new transaction with name [com.hbs.customer.CustomerService.customerLogin]
03:35:16,578 DEBUG HibernateTransactionManager:440 - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@dfbabd]
03:35:16,578 DEBUG HibernateTransactionManager:510 - Exposing Hibernate transaction as JDBC transaction [org.apache.commons.dbcp.PoolableConnection@1501026]
03:35:16,578 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@1672c01] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] to thread [http-8088-Processor25]
03:35:16,578 DEBUG TransactionSynchronizationManager:219 - Initializing transaction synchronization
03:35:16,578 DEBUG TransactionInterceptor:275 - Getting transaction for [com.hbs.customer.CustomerService.customerLogin]
用户登录
03:35:16,578 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,578 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,578 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:35:16,578 DEBUG SQL:393 - select this_.CUSTOMER_ID as CUSTOMER1_5_0_, this_.CUSTOMER_GROUP_ID as CUSTOMER2_5_0_, this_.CUSTOMER_PASSWORD as CUSTOMER3_5_0_, this_.CUSTOMER_NAME as CUSTOMER4_5_0_, this_.CUSTOMER_DESCRIPTION as CUSTOMER5_5_0_, this_.CUSTOMER_KIND as CUSTOMER6_5_0_, this_.CUSTOMER_SEX as CUSTOMER7_5_0_, this_.PHONE as PHONE5_0_, this_.MOBILE as MOBILE5_0_, this_.ADDRESS as ADDRESS5_0_, this_.EMAIL as EMAIL5_0_, this_.CONFIRM_TYPE as CONFIRM12_5_0_, this_.CREATE_TIME as CREATE13_5_0_, this_.GROUP_TIME as GROUP14_5_0_, this_.FIRST_TIME as FIRST15_5_0_, this_.LAST_TIME as LAST16_5_0_, this_.LOGIN_COUNT as LOGIN17_5_0_, this_.CREDIT_VALUE as CREDIT18_5_0_, this_.CUMULATE_VALUE as CUMULATE19_5_0_, this_.STATUS as STATUS5_0_, this_.NOTES as NOTES5_0_ from hbs.hbs_customer this_ where this_.CUSTOMER_ID=? and this_.CUSTOMER_PASSWORD=?
03:35:16,593 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
记录日志开始
03:35:16,593 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,593 DEBUG HibernateTransactionManager:390 - Found thread-bound Session [org.hibernate.impl.SessionImpl@dfbabd] for Hibernate transaction
03:35:16,593 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.jdbc.datasource.ConnectionHolder@1672c01] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] bound to thread [http-8088-Processor25]
03:35:16,593 DEBUG HibernateTransactionManager:292 - Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@5ec940]
03:35:16,593 DEBUG HibernateTransactionManager:358 - Suspending current transaction, creating new transaction with name [com.hbs.eventlog.EventLogService.eventLog]
03:35:16,593 DEBUG TransactionSynchronizationManager:272 - Clearing transaction synchronization
03:35:16,593 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] from thread [http-8088-Processor25]
03:35:16,609 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@1672c01] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] from thread [http-8088-Processor25]
03:35:16,609 DEBUG HibernateTransactionManager:428 - Opened new Session [org.hibernate.impl.SessionImpl@eeb406] for Hibernate transaction
03:35:16,609 DEBUG HibernateTransactionManager:440 - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@eeb406]
03:35:16,609 DEBUG HibernateTransactionManager:510 - Exposing Hibernate transaction as JDBC transaction [org.apache.commons.dbcp.PoolableConnection@8543aa]
03:35:16,609 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@16d03ba] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] to thread [http-8088-Processor25]
03:35:16,609 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] to thread [http-8088-Processor25]
03:35:16,609 DEBUG TransactionSynchronizationManager:219 - Initializing transaction synchronization
03:35:16,609 DEBUG TransactionInterceptor:275 - Getting transaction for [com.hbs.eventlog.EventLogService.eventLog]
03:35:16,625 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,625 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,625 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:35:16,625 DEBUG SQL:393 - select hotel0_.HOTEL_ID as HOTEL1_3_0_, hotel0_.HOTEL_NAME as HOTEL2_3_0_, hotel0_.DESCRIPTION as DESCRIPT3_3_0_, hotel0_.CHARACTERISTIC as CHARACTE4_3_0_, hotel0_.STAR_CLASS as STAR5_3_0_, hotel0_.ESTABLISH_DATE as ESTABLISH6_3_0_, hotel0_.BUSINESS_LICENSE as BUSINESS7_3_0_, hotel0_.LEGAL_PERSON as LEGAL8_3_0_, hotel0_.ADDRESS as ADDRESS3_0_, hotel0_.PHONE as PHONE3_0_, hotel0_.EMAIL as EMAIL3_0_, hotel0_.INTERNET_ADDRESS as INTERNET12_3_0_, hotel0_.HOTEL_LOG as HOTEL13_3_0_, hotel0_.COPYRIGHT as COPYRIGHT3_0_, hotel0_.NOTES as NOTES3_0_, hotel0_.CUR_ORDERFORM_ID as CUR16_3_0_ from hbs.hbs_hotel hotel0_ where hotel0_.HOTEL_ID=?
03:35:16,625 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
03:35:16,625 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,625 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] bound to thread [http-8088-Processor25]
03:35:16,625 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:35:16,625 DEBUG SQL:393 - update hbs.hbs_hotel set HOTEL_NAME=?, DESCRIPTION=?, CHARACTERISTIC=?, STAR_CLASS=?, ESTABLISH_DATE=?, BUSINESS_LICENSE=?, LEGAL_PERSON=?, ADDRESS=?, PHONE=?, EMAIL=?, INTERNET_ADDRESS=?, HOTEL_LOG=?, COPYRIGHT=?, NOTES=?, CUR_ORDERFORM_ID=? where HOTEL_ID=?
03:35:16,640 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
03:35:16,640 DEBUG TransactionInterceptor:305 - Completing transaction for [com.hbs.eventlog.EventLogService.eventLog]
03:35:16,640 DEBUG HibernateTransactionManager:776 - Triggering beforeCommit synchronization
03:35:16,640 DEBUG HibernateTransactionManager:789 - Triggering beforeCompletion synchronization
03:35:16,640 DEBUG HibernateTransactionManager:609 - Initiating transaction commit
03:35:16,640 DEBUG HibernateTransactionManager:557 - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@eeb406]
03:35:16,671 DEBUG HibernateTransactionManager:802 - Triggering afterCommit synchronization
03:35:16,671 DEBUG HibernateTransactionManager:818 - Triggering afterCompletion synchronization
03:35:16,671 DEBUG TransactionSynchronizationManager:272 - Clearing transaction synchronization
03:35:16,671 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.orm.hibernate3.SessionHolder@fbfa2] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] from thread [http-8088-Processor25]
03:35:16,671 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@16d03ba] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] from thread [http-8088-Processor25]
03:35:16,671 DEBUG HibernateTransactionManager:636 - Closing Hibernate Session [org.hibernate.impl.SessionImpl@eeb406] after transaction
03:35:16,671 DEBUG SessionFactoryUtils:781 - Closing Hibernate Session
03:35:16,671 DEBUG HibernateTransactionManager:870 - Resuming suspended transaction
03:35:16,671 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] to thread [http-8088-Processor25]
03:35:16,671 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@1672c01] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] to thread [http-8088-Processor25]
03:35:16,671 DEBUG TransactionSynchronizationManager:219 - Initializing transaction synchronization
记录日志结束
03:35:16,671 DEBUG TransactionInterceptor:320 - Completing transaction for [com.hbs.customer.CustomerService.customerLogin] after exception: com.hbs.common.ResultException: 登录失败！用户名或密码不正确
03:35:16,671 DEBUG RuleBasedTransactionAttribute:130 - Applying rules to determine whether transaction should rollback on com.hbs.common.ResultException: 登录失败！用户名或密码不正确
03:35:16,687 DEBUG RuleBasedTransactionAttribute:148 - Winning rollback rule is: RollbackRuleAttribute with pattern [Exception]
03:35:16,687 DEBUG HibernateTransactionManager:789 - Triggering beforeCompletion synchronization
03:35:16,687 DEBUG HibernateTransactionManager:700 - Initiating transaction rollback
03:35:16,687 DEBUG HibernateTransactionManager:576 - Rolling back Hibernate transaction on Session [org.hibernate.impl.SessionImpl@dfbabd]
03:35:16,687 DEBUG HibernateTransactionManager:818 - Triggering afterCompletion synchronization
03:35:16,687 DEBUG TransactionSynchronizationManager:272 - Clearing transaction synchronization
03:35:16,687 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@1672c01] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] from thread [http-8088-Processor25]
03:35:16,687 DEBUG HibernateTransactionManager:643 - Not closing pre-bound Hibernate Session [org.hibernate.impl.SessionImpl@dfbabd] after transaction
03:35:16,687 WARN ActionMapping:74 - Unable to find 'null' forward.
03:35:16,687 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.orm.hibernate3.SessionHolder@1fee2db] for key [org.hibernate.impl.SessionFactoryImpl@1fe3238] from thread [http-8088-Processor25]
03:35:16,687 DEBUG OpenSessionInViewFilter:221 - Closing single Hibernate Session in OpenSessionInViewFilter
03:35:16,687 DEBUG SessionFactoryUtils:781 - Closing Hibernate Session
从中可以看出，log异常拦截器在用户登录的事务回滚之前截获异常，在记录日志时，日志记录的service方法也在spring的事务管理之下，用户登录的事务还没有结束，根据REQUIRES_NEW特性，spring会新开一个事务，这时原来的数据库连接已经在一个事务中，一个连接不可能同时有两个事务，所以同时新创建一个session连接（虽然我使用了OpenSessionInViewFilter，并且session是单例的），日志记录就在新建的事务和session中进行，完了提交，并且会把新建的session连接关闭。
然后继续进行被中断的用户登录的事务管理操作，由于抛异常spring将用户登录的事务回滚。
这样能够实现预想的功能，但是如果我去掉指定的REQUIRES_NEW，那么log记录的操作会继续在用户登录的事务中进行，最后会被一起回滚。
如果我把事务管理的order设为2，log拦截器的order设为1，也就是log拦截器在事务管理拦截器的外面，会在事务管理拦截器前后执行完了再执行log的异常拦截器，打印信息如下：
03:53:46,125 DEBUG OpenSessionInViewFilter:253 - Using SessionFactory 'sessionFactory' for OpenSessionInViewFilter
03:53:46,156 DEBUG OpenSessionInViewFilter:196 - Opening single Hibernate Session in OpenSessionInViewFilter
03:53:46,156 DEBUG SessionFactoryUtils:333 - Opening Hibernate Session
03:53:46,265 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] to thread [http-8088-Processor25]
03:53:46,296 INFO ComposableRequestProcessor:144 - Initializing composable request processor for module prefix ''
03:53:46,375 INFO CreateAction:65 - Initialize action of type: org.springframework.web.struts.DelegatingActionProxy
03:53:46,406 INFO JdbcTransactionObjectSupport:60 - JDBC 3.0 Savepoint class is available
03:53:46,406 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,406 DEBUG HibernateTransactionManager:390 - Found thread-bound Session [org.hibernate.impl.SessionImpl@c21d01] for Hibernate transaction
03:53:46,406 DEBUG HibernateTransactionManager:292 - Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@1fe6783]
03:53:46,406 DEBUG HibernateTransactionManager:320 - Creating new transaction with name [com.hbs.customer.CustomerService.customerLogin]
03:53:46,421 DEBUG HibernateTransactionManager:440 - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@c21d01]
03:53:46,468 DEBUG HibernateTransactionManager:510 - Exposing Hibernate transaction as JDBC transaction [org.apache.commons.dbcp.PoolableConnection@16c02df]
03:53:46,468 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@30803a] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] to thread [http-8088-Processor25]
03:53:46,468 DEBUG TransactionSynchronizationManager:219 - Initializing transaction synchronization
03:53:46,484 DEBUG TransactionInterceptor:275 - Getting transaction for [com.hbs.customer.CustomerService.customerLogin]
用户登录
03:53:46,500 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,500 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,515 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:53:46,531 DEBUG SQL:393 - select this_.CUSTOMER_ID as CUSTOMER1_5_0_, this_.CUSTOMER_GROUP_ID as CUSTOMER2_5_0_, this_.CUSTOMER_PASSWORD as CUSTOMER3_5_0_, this_.CUSTOMER_NAME as CUSTOMER4_5_0_, this_.CUSTOMER_DESCRIPTION as CUSTOMER5_5_0_, this_.CUSTOMER_KIND as CUSTOMER6_5_0_, this_.CUSTOMER_SEX as CUSTOMER7_5_0_, this_.PHONE as PHONE5_0_, this_.MOBILE as MOBILE5_0_, this_.ADDRESS as ADDRESS5_0_, this_.EMAIL as EMAIL5_0_, this_.CONFIRM_TYPE as CONFIRM12_5_0_, this_.CREATE_TIME as CREATE13_5_0_, this_.GROUP_TIME as GROUP14_5_0_, this_.FIRST_TIME as FIRST15_5_0_, this_.LAST_TIME as LAST16_5_0_, this_.LOGIN_COUNT as LOGIN17_5_0_, this_.CREDIT_VALUE as CREDIT18_5_0_, this_.CUMULATE_VALUE as CUMULATE19_5_0_, this_.STATUS as STATUS5_0_, this_.NOTES as NOTES5_0_ from hbs.hbs_customer this_ where this_.CUSTOMER_ID=? and this_.CUSTOMER_PASSWORD=?
03:53:46,593 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
03:53:46,593 DEBUG TransactionInterceptor:320 - Completing transaction for [com.hbs.customer.CustomerService.customerLogin] after exception: com.hbs.common.ResultException: 登录失败！用户名或密码不正确
03:53:46,609 DEBUG RuleBasedTransactionAttribute:130 - Applying rules to determine whether transaction should rollback on com.hbs.common.ResultException: 登录失败！用户名或密码不正确
03:53:46,609 DEBUG RuleBasedTransactionAttribute:148 - Winning rollback rule is: RollbackRuleAttribute with pattern [Exception]
03:53:46,609 DEBUG HibernateTransactionManager:789 - Triggering beforeCompletion synchronization
03:53:46,609 DEBUG HibernateTransactionManager:700 - Initiating transaction rollback
03:53:46,609 DEBUG HibernateTransactionManager:576 - Rolling back Hibernate transaction on Session [org.hibernate.impl.SessionImpl@c21d01]
03:53:46,609 DEBUG HibernateTransactionManager:818 - Triggering afterCompletion synchronization
03:53:46,609 DEBUG TransactionSynchronizationManager:272 - Clearing transaction synchronization
03:53:46,609 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@30803a] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] from thread [http-8088-Processor25]
03:53:46,625 DEBUG HibernateTransactionManager:643 - Not closing pre-bound Hibernate Session [org.hibernate.impl.SessionImpl@c21d01] after transaction
记录日志开始
03:53:46,640 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,640 DEBUG HibernateTransactionManager:390 - Found thread-bound Session [org.hibernate.impl.SessionImpl@c21d01] for Hibernate transaction
03:53:46,640 DEBUG HibernateTransactionManager:292 - Using transaction object [org.springframework.orm.hibernate3.HibernateTransactionManager$HibernateTransactionObject@1f68336]
03:53:46,640 DEBUG HibernateTransactionManager:320 - Creating new transaction with name [com.hbs.eventlog.EventLogService.eventLog]
03:53:46,640 DEBUG HibernateTransactionManager:440 - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@c21d01]
03:53:46,640 DEBUG HibernateTransactionManager:510 - Exposing Hibernate transaction as JDBC transaction [org.apache.commons.dbcp.PoolableConnection@16c02df]
03:53:46,640 DEBUG TransactionSynchronizationManager:166 - Bound value [org.springframework.jdbc.datasource.ConnectionHolder@1205042] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] to thread [http-8088-Processor25]
03:53:46,656 DEBUG TransactionSynchronizationManager:219 - Initializing transaction synchronization
03:53:46,656 DEBUG TransactionInterceptor:275 - Getting transaction for [com.hbs.eventlog.EventLogService.eventLog]
03:53:46,656 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,656 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,656 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:53:46,656 DEBUG SQL:393 - select hotel0_.HOTEL_ID as HOTEL1_3_0_, hotel0_.HOTEL_NAME as HOTEL2_3_0_, hotel0_.DESCRIPTION as DESCRIPT3_3_0_, hotel0_.CHARACTERISTIC as CHARACTE4_3_0_, hotel0_.STAR_CLASS as STAR5_3_0_, hotel0_.ESTABLISH_DATE as ESTABLISH6_3_0_, hotel0_.BUSINESS_LICENSE as BUSINESS7_3_0_, hotel0_.LEGAL_PERSON as LEGAL8_3_0_, hotel0_.ADDRESS as ADDRESS3_0_, hotel0_.PHONE as PHONE3_0_, hotel0_.EMAIL as EMAIL3_0_, hotel0_.INTERNET_ADDRESS as INTERNET12_3_0_, hotel0_.HOTEL_LOG as HOTEL13_3_0_, hotel0_.COPYRIGHT as COPYRIGHT3_0_, hotel0_.NOTES as NOTES3_0_, hotel0_.CUR_ORDERFORM_ID as CUR16_3_0_ from hbs.hbs_hotel hotel0_ where hotel0_.HOTEL_ID=?
03:53:46,718 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
03:53:46,734 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,734 DEBUG TransactionSynchronizationManager:139 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] bound to thread [http-8088-Processor25]
03:53:46,734 DEBUG HibernateTemplate:354 - Found thread-bound Session for HibernateTemplate
03:53:46,812 DEBUG SQL:393 - update hbs.hbs_hotel set HOTEL_NAME=?, DESCRIPTION=?, CHARACTERISTIC=?, STAR_CLASS=?, ESTABLISH_DATE=?, BUSINESS_LICENSE=?, LEGAL_PERSON=?, ADDRESS=?, PHONE=?, EMAIL=?, INTERNET_ADDRESS=?, HOTEL_LOG=?, COPYRIGHT=?, NOTES=?, CUR_ORDERFORM_ID=? where HOTEL_ID=?
03:53:46,812 DEBUG HibernateTemplate:378 - Not closing pre-bound Hibernate Session after HibernateTemplate
03:53:46,812 DEBUG TransactionInterceptor:305 - Completing transaction for [com.hbs.eventlog.EventLogService.eventLog]
03:53:46,812 DEBUG HibernateTransactionManager:776 - Triggering beforeCommit synchronization
03:53:46,812 DEBUG HibernateTransactionManager:789 - Triggering beforeCompletion synchronization
03:53:46,812 DEBUG HibernateTransactionManager:609 - Initiating transaction commit
03:53:46,812 DEBUG HibernateTransactionManager:557 - Committing Hibernate transaction on Session [org.hibernate.impl.SessionImpl@c21d01]
03:53:46,859 DEBUG HibernateTransactionManager:802 - Triggering afterCommit synchronization
03:53:46,859 DEBUG HibernateTransactionManager:818 - Triggering afterCompletion synchronization
03:53:46,859 DEBUG TransactionSynchronizationManager:272 - Clearing transaction synchronization
03:53:46,859 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.jdbc.datasource.ConnectionHolder@1205042] for key [org.apache.commons.dbcp.BasicDataSource@54cbb9] from thread [http-8088-Processor25]
03:53:46,859 DEBUG HibernateTransactionManager:643 - Not closing pre-bound Hibernate Session [org.hibernate.impl.SessionImpl@c21d01] after transaction
记录日志结束
03:53:46,859 WARN ActionMapping:74 - Unable to find 'null' forward.
03:53:46,859 DEBUG TransactionSynchronizationManager:190 - Removed value [org.springframework.orm.hibernate3.SessionHolder@889c4e] for key [org.hibernate.impl.SessionFactoryImpl@cdf872] from thread [http-8088-Processor25]
03:53:46,859 DEBUG OpenSessionInViewFilter:221 - Closing single Hibernate Session in OpenSessionInViewFilter
03:53:46,875 DEBUG SessionFactoryUtils:781 - Closing Hibernate Session
可以看出，用户登录的事务和日志记录的事务是前后两个不相关的事务，并且在日志记录事务中并不需要新建session连接，而是直接用在OpenSessionInViewFilter中创建的session。实际上这时也并不需要将propagation设为REQUIRES_NEW，使用默认的REQUIRES也照样能够正常工作。
所以应该将该异常拦截器设在事务管理拦截器的外面，即使用Order接口排在前面。