4

引言

再回顾一下问题场景:

clipboard.png

Iterable<Teacher> teachers = teacherRepository.findAll();
for (Teacher teacher : teachers) {
    logger.debug("教师: " + teacher.getName());

    for (Klass klass : teacher.getKlasses()) {
        logger.debug("班级: " + klass.getName());

        for (Student student : klass.getStudents()) {
            logger.debug("学生: " + student.getName());
        }
    }
}

在单元测试中跑这段代码,是报错的,no Session,说明执行完teacherRepository.findAll()之后,session就已经关闭了。继续执行,session已经关闭,再去数据库查教师关联的班级信息,就错了。

clipboard.png

然而呢?把这段代码再放到Service里,写一个接口,交给浏览器去调用,却正常执行,说明session还在。

clipboard.png

然后就一直研究为什么不好使?如果能把这个原因分析明白,以后再遇到no session错误的时候就可以一劳永逸了。

探究

调试

调试最简单的方法就是中断,但是咱水平还不行,也不知道JPA内部去找Hibernate怎么调用的,中断哪个方法呢?

后台发现了另一种调试的方法,JPA的源码中也是像我们开发时经常写日志的,logger.debug()什么的。

slf4j中常用的日志级别就ERROR、WARN、INFO、DEBUG四种,我们可以将JPA的日志级别设置为DEBUG级别,这样我们就可以根据日志推测到JPA内部到底是怎么执行的了。

修改日志级别

logging.level.org.springframework.orm.jpa=debug

修改配置文件,将JPA的日志级别设置为DEBUG

在单元测试中执行

clipboard.png

完整日志:

2019-06-06 11:36:40.415 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2019-06-06 11:36:40.416 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1334204880<open>)] for JPA transaction
2019-06-06 11:36:40.429 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@73b74615]
2019-06-06 11:36:40.449  INFO 11391 --- [           main] o.h.h.i.QueryTranslatorFactoryInitiator  : HHH000397: Using ASTQueryTranslatorFactory
Hibernate: select teacher0_.id as id1_2_, teacher0_.name as name2_2_ from teacher teacher0_
2019-06-06 11:36:40.598 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-06-06 11:36:40.598 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1334204880<open>)]
2019-06-06 11:36:40.601 DEBUG 11391 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1334204880<open>)] after transaction
2019-06-06 11:36:40.602 DEBUG 11391 --- [           main] com.yunzhiclub.jpa.JpaApplicationTests   : 教师: 张三

org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.yunzhiclub.jpa.entity.Teacher.klasses, could not initialize proxy - no Session

分析

Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
Opened new EntityManager [SessionImpl(1334204880<open>)] for JPA transaction
Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@73b74615]
HHH000397: Using ASTQueryTranslatorFactory
Hibernate: select teacher0_.id as id1_2_, teacher0_.name as name2_2_ from teacher teacher0_
Initiating transaction commit
Committing JPA transaction on EntityManager [SessionImpl(1334204880<open>)]

上来是先执行了一个事务,为什么会有事务呢?

JPA创建的仓库实现是SimpleJpaRepository,我们看看源码:

clipboard.png

实现类上添加了事务注解,并采用了默认的REQUIRED传播级别。

如果当前存在事务,则使用当前事务。如果不存在任何事务,则创建一个新的事务。

当前不存在事务,所以是teacherRepository.findAll()方法自己创建的事务。

Hibernate: select teacher0_.id as id1_2_, teacher0_.name as name2_2_ from teacher teacher0_
Initiating transaction commit
Committing JPA transaction on EntityManager [SessionImpl(1334204880<open>)]
Closing JPA EntityManager [SessionImpl(1334204880<open>)] after transaction
教师: 张三

org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.yunzhiclub.jpa.entity.Teacher.klasses, could not initialize proxy - no Session

再接着看下面的日志,执行了数据库的查询操作,提交了一个事务,然后Closing JPA EntityManager [SessionImpl(1334204880<open>)] after transaction

事务执行之后,就关闭了EntityManager,也就是Hibernate中的Session

Session is a hibernate-specific API, EntityManager is a standardized API for JPA. 

EntityManagerSession还是有一些差别的,但是我们目前还未接触到底层的实现,只需要把他们当成一个东西,只不过在不同领域叫法不同罢了。

SpringMVC中执行

clipboard.png

执行得很顺利,完整日志如下:

2019-06-06 11:58:28.788 DEBUG 11443 --- [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2019-06-06 11:58:28.800 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(193939447<open>)] for JPA transaction
2019-06-06 11:58:28.800 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2019-06-06 11:58:28.808 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@56eb5438]
2019-06-06 11:58:28.820  INFO 11443 --- [nio-8080-exec-1] o.h.h.i.QueryTranslatorFactoryInitiator  : HHH000397: Using ASTQueryTranslatorFactory
Hibernate: select teacher0_.id as id1_2_, teacher0_.name as name2_2_ from teacher teacher0_
2019-06-06 11:58:28.897 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2019-06-06 11:58:28.898 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(193939447<open>)]
2019-06-06 11:58:28.901 DEBUG 11443 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2019-06-06 11:58:28.902 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 教师: 张三
Hibernate: select klasses0_.teacher_id as teacher_3_0_0_, klasses0_.id as id1_0_0_, klasses0_.id as id1_0_1_, klasses0_.name as name2_0_1_, klasses0_.teacher_id as teacher_3_0_1_ from klass klasses0_ where klasses0_.teacher_id=?
2019-06-06 11:58:28.915 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 班级: 软件工程
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
2019-06-06 11:58:28.917 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: Hello Kitty
2019-06-06 11:58:28.917 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 史努比
2019-06-06 11:58:28.917 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 班级: 网络工程
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
2019-06-06 11:58:28.919 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 米老鼠
2019-06-06 11:58:28.919 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 唐老鸭
2019-06-06 11:58:28.919 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 教师: 李四
Hibernate: select klasses0_.teacher_id as teacher_3_0_0_, klasses0_.id as id1_0_0_, klasses0_.id as id1_0_1_, klasses0_.name as name2_0_1_, klasses0_.teacher_id as teacher_3_0_1_ from klass klasses0_ where klasses0_.teacher_id=?
2019-06-06 11:58:28.921 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 班级: 计算机科学与技术
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
2019-06-06 11:58:28.923 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 哪吒
2019-06-06 11:58:28.923 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 小竹熊
2019-06-06 11:58:28.923 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 班级: 物联网
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
2019-06-06 11:58:28.925 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 喜羊羊
2019-06-06 11:58:28.925 DEBUG 11443 --- [nio-8080-exec-1] c.y.jpa.service.TeacherServiceImpl       : 学生: 灰太狼
2019-06-06 11:58:28.944 DEBUG 11443 --- [nio-8080-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor

分析

Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
Found thread-bound EntityManager [SessionImpl(193939447<open>)] for JPA transaction
Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@56eb5438]
HHH000397: Using ASTQueryTranslatorFactory
Hibernate: select teacher0_.id as id1_2_, teacher0_.name as name2_2_ from teacher teacher0_
Initiating transaction commit
Committing JPA transaction on EntityManager [SessionImpl(193939447<open>)]

这段没什么说的,和上面一样,创建事务,执行完提交事务。

Not closing pre-bound JPA EntityManager after transaction
教师: 张三
Hibernate: select klasses0_.teacher_id as teacher_3_0_0_, klasses0_.id as id1_0_0_, klasses0_.id as id1_0_1_, klasses0_.name as name2_0_1_, klasses0_.teacher_id as teacher_3_0_1_ from klass klasses0_ where klasses0_.teacher_id=?
班级: 软件工程
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
学生: Hello Kitty
学生: 史努比
班级: 网络工程
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
学生: 米老鼠
学生: 唐老鸭
教师: 李四
Hibernate: select klasses0_.teacher_id as teacher_3_0_0_, klasses0_.id as id1_0_0_, klasses0_.id as id1_0_1_, klasses0_.name as name2_0_1_, klasses0_.teacher_id as teacher_3_0_1_ from klass klasses0_ where klasses0_.teacher_id=?
班级: 计算机科学与技术
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
学生: 哪吒
学生: 小竹熊
班级: 物联网
Hibernate: select students0_.klass_id as klass_id4_1_0_, students0_.id as id1_1_0_, students0_.id as id1_1_1_, students0_.email as email2_1_1_, students0_.klass_id as klass_id4_1_1_, students0_.name as name3_1_1_ from student students0_ where students0_.klass_id=?
学生: 喜羊羊
学生: 灰太狼
Closing JPA EntityManager in OpenEntityManagerInViewInterceptor

这块就有意思了。

第一行:Not closing pre-bound JPA EntityManager after transaction

最后一行:Closing JPA EntityManager in OpenEntityManagerInViewInterceptor

在事务之后没有关闭Session,一直到最后,才将Session关闭,所以没出错。

而在单元测试中呢?Closing JPA EntityManager [SessionImpl(1334204880<open>)] after transaction,事务执行之后就关闭了Session,所以出错了。

原因

找着关键了,Service里好使是因为SessionfindAll的事务执行完之后没有关闭。

之前怎么没发现呢?StackOverflow上这老哥和我是一样的问题:Hibernate jpa entity manager not being closed in spring service layer - StackOverflow

clipboard.png

UserAddress一对多。

clipboard.png

我写了一个getUser方法,惰性加载的一对多,但是为什么序列化的时候去找addresses的时候,它不报lazy initialization的错误呢?

这是回答,大家注意一下我圈起来的几个关键词:

clipboard.png

OpenEntityManagerInViewInterceptor:在Spring Boot项目中,Session是归OpenEntityManagerInViewInterceptor管理的,这个是干什么的呢?

它是确保EntityManager(Session)一直保持开启的状态,直到请求结束之后(complete request)。所以session在本次请求中,一直open着,惰性加载的数据随便查。

如果你不想这么干,你可以配置spring.jpa.open-in-view=false来禁用此行为。

spring.jpa.open-in-view配置为false作一把。

clipboard.png

果然,session关闭了,报错位置在TeacherServiceImpl28行,就是查询惰性加载的klasses出错了。

clipboard.png

总结

从上周想到这个问题开始,到今天解决,也是花了许久的时间。

所以以后再遇到no session的问题,如果是在项目里的,就先去想想是不是complete request了,请求结束前,session一直有效。

如果是在单元测试中,就去想想是不是事务配错了,导致session挂掉了。

clipboard.png

兹可谓一劳而久逸。暂费而永无宁者也。 ——班固《封燕然山铭》

一劳永逸,这是程序员最快乐的时候。


张喜硕
2.1k 声望423 粉丝

浅梦辄止,书墨未浓。