使用Hibernate和Spring Data JPA激活SQL语句记录

Question

我有一个使用Hibernate作为提供程序的Spring Data JPA仓库。我想记录SQL语句，但我无法实现。我尝试了各种解决方案：

• 在我的HibernateJpaVendorAdapter中将showSql设置为true
• 在我的log4j.properties文件中添加log4j.logger.org.hibernate.SQL=DEBUG（值得一提的是，log4j.logger.org.hibernate=INFO确实添加了一些日志信息，但log4j.logger.org.hibernate.SQL=DEBUG没有）

这里是我的类和配置文件：

DatabaseConfiguration.java

/**
 * Database configuration
 *
 * @author dupirefr
 */
@Configuration
@Import({BaseConfiguration.class, DatabaseProperties.class})
@EnableJpaRepositories(basePackages = DatabaseConfiguration.REPOSITORIES_PACKAGE)
public class DatabaseConfiguration {

    /*
     * Constants
     */
    public static final String MODEL_PACKAGE = "be.dupirefr.examples.spring.batch.simple.model";
    public static final String REPOSITORIES_PACKAGE = "be.dupirefr.examples.spring.batch.simple.repositories";

    /*
     * Beans
     */
    @Bean
    public DataSource dataSource(DatabaseProperties properties) {
        DriverManagerDataSource dataSource = new DriverManagerDataSource();
        dataSource.setUrl(properties.url);
        dataSource.setUsername(properties.username);
        dataSource.setPassword(properties.password);
        dataSource.setDriverClassName(properties.driverClassName);

        return dataSource;
    }

    @Bean
    public LocalContainerEntityManagerFactoryBean entityManagerFactory(DataSource dataSource) {
        LocalContainerEntityManagerFactoryBean entityManagerFactoryBean = new LocalContainerEntityManagerFactoryBean();
        entityManagerFactoryBean.setDataSource(dataSource);
        entityManagerFactoryBean.setPackagesToScan(MODEL_PACKAGE);
        entityManagerFactoryBean.setJpaVendorAdapter(new HibernateJpaVendorAdapter());
        return entityManagerFactoryBean;
    }

    @Bean
    public PlatformTransactionManager transactionManager(DataSource dataSource) {
        return new DataSourceTransactionManager(dataSource);
    }

}

database.properties

# Data source
spring.datasource.url=jdbc:h2:mem:test
spring.datasource.username=admin
spring.datasource.password=admin
spring.datasource.driver-class-name=org.h2.Driver

DatabaseProperties.java

/**
 * Database properties
 *
 * @author dupirefr
 */
@Configuration
@PropertySource("classpath:be/dupirefr/examples/spring/batch/simple/config/database/database.properties")
public class DatabaseProperties {

    /*
     * Fields
     */
    @Value("${spring.datasource.url}")
    public String url;

    @Value("${spring.datasource.username}")
    public String username;

    @Value("${spring.datasource.password}")
    public String password;

    @Value("${spring.datasource.driver-class-name}")
    public String driverClassName;

}

EmployerRepository.java

/**
 * {@link Employer}'s repository
 *
 * @author dupirefr
 */
@Repository
public interface EmployerRepository extends JpaRepository<Employer, Long> {

}

EmployerRepositoryIT.java

/**
 * {@link EmployerRepository}'s integration test
 *
 * @author dupirefr
 */
@RunWith(SpringRunner.class)
@ContextConfiguration(classes = DatabaseConfiguration.class)
@Transactional
public class EmployerRepositoryIT {

    /*
     * Constants
     */
    public static final Employer GOOGLE = new Employer(1L, "Google");
    public static final Employer MICROSOFT = new Employer(2L, "Microsoft");
    public static final Employer APPLE = new Employer(3L, "Apple");

    /*
     * Fields
     */
    @Autowired
    private EmployerRepository repository;

    @Autowired
    private EntityManager entityManager;

    /*
     * Setups
     */
    @Before
    public void setUp() {
        entityManager.persist(GOOGLE);
        entityManager.persist(MICROSOFT);
    }

    /*
     * Tests
     */
    @Test
    public void findById_Exists() {
        assertEquals(GOOGLE, repository.findById(GOOGLE.getId()).get());
        assertEquals(MICROSOFT, repository.findById(MICROSOFT.getId()).get());
    }

    @Test
    public void findById_NotExists() {
        assertFalse(repository.findById(Long.MAX_VALUE).isPresent());
    }

    @Test
    public void findAll() {
        assertEquals(Arrays.asList(GOOGLE, MICROSOFT), repository.findAll());
    }

    @Test
    public void save() {
        repository.save(APPLE);
        assertEquals(APPLE, entityManager.find(Employer.class, APPLE.getId()));
    }

    @Test
    public void delete() {
        repository.delete(MICROSOFT);
        assertNull(entityManager.find(Employer.class, MICROSOFT.getId()));
    }

}

log4j.properties

# Appenders
## Console
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

# Loggers
## Root
log4j.rootLogger=INFO, stdout

## Hibernate
### Generic
log4j.logger.org.hibernate=INFO
### SQL statements
log4j.logger.org.hibernate.SQL=DEBUG

为什么之前的解决方案都没有起作用？Spring Data JPA和Hibernate SQL日志配置之间是否存在某种不兼容性？

编辑： 我尝试了评论中提出的两个解决方案，但都没有生效。我还尝试更改我使用的数据库（从H2到HSQL）或指定Hibernate方言，但都没有生效。事实上，在使用Spring时，对于某些数据库，Hibernate方言会自动找到。

编辑2： 我尝试将rootLogger的日志级别更改为TRACE。我还尝试为appender明确指定阈值。最后，我尝试添加具有showSql = true的JpaProperties，但它们都没有起作用。我认为有些非常明显的事情可以做，但我错过了完整的情况:-/

编辑3： 直接调用记录器，如下面的测试所示，确实有效。我开始怀疑是否存在打字错误或其他问题，防止Hibernate使用记录器。

@Test
public void delete() {
    LoggerFactory.getLogger("org.hibernate.SQL").debug("delete()");
    repository.delete(MICROSOFT);
    assertNull(entityManager.find(Employer.class, MICROSOFT.getId()));
}

以下是生成的日志记录：

10:33:45,158  INFO DefaultTestContextBootstrapper:257 - Loaded default TestExecutionListener class names from location [META-INF/spring.factories]: [org.springframework.test.context.web.ServletTestExecutionListener, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener, org.springframework.test.context.support.DependencyInjectionTestExecutionListener, org.springframework.test.context.support.DirtiesContextTestExecutionListener, org.springframework.test.context.transaction.TransactionalTestExecutionListener, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener]
10:33:45,183  INFO DefaultTestContextBootstrapper:206 - Could not instantiate TestExecutionListener [org.springframework.test.context.web.ServletTestExecutionListener]. Specify custom listener classes or make the default listener classes (and their required dependencies) available. Offending class: [javax/servlet/ServletContext]
10:33:45,185  INFO DefaultTestContextBootstrapper:184 - Using TestExecutionListeners: [org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@1f28c152, org.springframework.test.context.support.DependencyInjectionTestExecutionListener@7d907bac, org.springframework.test.context.support.DirtiesContextTestExecutionListener@7791a895, org.springframework.test.context.transaction.TransactionalTestExecutionListener@3a5ed7a6, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener@6325a3ee]10:33:45,376  INFO GenericApplicationContext:589 - Refreshing org.springframework.context.support.GenericApplicationContext@4493d195: startup date [Sun Jan 14 10:33:45 CET 2018]; root of context hierarchy
10:33:46,187  WARN ConfigurationClassEnhancer:353 - @Bean method BaseConfiguration.propertySourcesPlaceholderConfigurer is non-static and returns an object assignable to Spring's BeanFactoryPostProcessor interface. This will result in a failure to process annotations such as @Autowired, @Resource and @PostConstruct within the method's declaring @Configuration class. Add the 'static' modifier to this method to avoid these container lifecycle issues; see @Bean javadoc for complete details.
10:33:46,448  INFO DriverManagerDataSource:133 - Loaded JDBC driver: org.h2.Driver
10:33:46,743  INFO LocalContainerEntityManagerFactoryBean:361 - Building JPA container EntityManagerFactory for persistence unit 'default'
10:33:46,798  INFO LogHelper:31 - HHH000204: Processing PersistenceUnitInfo [
    name: default
    ...]
10:33:46,922  INFO Version:45 - HHH000412: Hibernate Core {5.2.12.Final}
10:33:46,924  INFO Environment:213 - HHH000206: hibernate.properties not found
10:33:46,979  INFO Version:66 - HCANN000001: Hibernate Commons Annotations {5.0.1.Final}
10:33:47,318  INFO Dialect:157 - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
10:33:48,472  INFO LocalContainerEntityManagerFactoryBean:393 - Initialized JPA EntityManagerFactory for persistence unit 'default'
10:33:49,422  INFO TransactionContext:105 - Began transaction (1) for test context [DefaultTestContext@2e3f79a2 testClass = EmployerRepositoryIT, testInstance = be.dupirefr.examples.spring.batch.simple.repositories.EmployerRepositoryIT@1460c81d, testMethod = delete@EmployerRepositoryIT, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@38b5f25 testClass = EmployerRepositoryIT, locations = '{}', classes = '{class be.dupirefr.examples.spring.batch.simple.config.database.DatabaseConfiguration}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{}', contextCustomizers = set[[empty]], contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader', parent = [null]], attributes = map[[empty]]]; transaction manager [org.springframework.jdbc.datasource.DataSourceTransactionManager@5b22b970]; rollback [true]
10:33:49,468 DEBUG SQL:83 - delete()
10:33:49,512  INFO TransactionContext:137 - Rolled back transaction for test context [DefaultTestContext@2e3f79a2 testClass = EmployerRepositoryIT, testInstance = be.dupirefr.examples.spring.batch.simple.repositories.EmployerRepositoryIT@1460c81d, testMethod = delete@EmployerRepositoryIT, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@38b5f25 testClass = EmployerRepositoryIT, locations = '{}', classes = '{class be.dupirefr.examples.spring.batch.simple.config.database.DatabaseConfiguration}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{}', contextCustomizers = set[[empty]], contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader', parent = [null]], attributes = map[[empty]]].
10:33:49,516  INFO GenericApplicationContext:989 - Closing org.springframework.context.support.GenericApplicationContext@4493d195: startup date [Sun Jan 14 10:33:45 CET 2018]; root of context hierarchy
10:33:49,519  INFO LocalContainerEntityManagerFactoryBean:571 - Closing JPA EntityManagerFactory for persistence unit 'default'

编辑 3： 我终于弄清楚了发生了什么。我注意到在失败的测试中，日志中发布了SQL查询。通过微调我的log4j属性，我发现它们来自hibernate日志记录器，正如预期的那样。

但是成功的操作没有发布日志。这是因为它们没有到达数据库。一切都发生在实体管理器中，因此不需要SQL。现在我知道我只是遇到了我的H2数据库问题，我需要找出解决方法。

- François Dupire

---

尝试在属性文件中添加 logging.level.org.hibernate.SQL=DEBUG logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE 并查看？ - Ahmed Raaj

你说过 log4j.logger.org.hibernate=INFO 添加了部分日志，但是 log4j.logger.org.hibernate.SQL=DEBUG 没有生效。你尝试过使用 log4j.logger.org.hibernate=DEBUG 吗？或者上面有拼写错误吗？ - dimwittedanimal

@AhmedRaaj：这些属性必须放在Spring属性文件中（例如application.properties）。我没有，我没有使用Spring Boot。我尝试将log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=TRACE添加到我的log4j.properties文件中，但由于此记录器的目标是显示绑定参数，因此它没有任何效果。 - François Dupire

@dimwittedanimal：那里没有打字错误:-)。我提到log4j.logger.org.hibernate是为了指出它对日志记录产生了影响，而另一个则没有（我觉得这很奇怪）。我尝试将DEBUG级别设置为前者的记录器，但仍然没有查询信息（因为这不是预期的工作）。 - François Dupire

Answer 1

替换：

log4j.rootLogger=INFO, stdout

随着

log4j.rootLogger=TRACE, stdout

And possibly add

log4j.logger.org.hibernate.type.descriptor.sql=TRACE

如果您也想获取绑定变量的值。

您已经正确配置了日志记录，但是您的appender只记录了INFO级别的日志，而SQL语句是在DEBUG级别下记录的。

- Jens Schauder

---

看起来确实很合理 :-). 我今晚会尝试一下，然后再回来告诉你结果！ - François Dupire

我刚试了一下，但它没有起作用。想想也是预料之中的，因为它只改变了根记录器的日志级别，而不是附加器的阈值（顺便说一下，我也试图更改它，但也没有起作用）。还是谢谢你的尝试。 - François Dupire

不确定您所说的appender阈值是什么意思。除了根记录器的配置之外，appender没有阈值。 - Jens Schauder

对于附加器，有一个阈值参数，与记录器的日志级别无关。它允许不同的附加器之间的日志不同，而无需更改记录器的日志级别。例如，如果您想在控制台中记录所有内容，但只想在文件中记录错误，您可以配置具有不同阈值的附加器，而不必触及记录器的配置。 - François Dupire

好的，现在明白了。 - Jens Schauder

Answer 2

尝试使用以下方法：

@Bean
public LocalContainerEntityManagerFactoryBean entityManagerFactory(DataSource dataSource) {
    LocalContainerEntityManagerFactoryBean entityManagerFactoryBean = new LocalContainerEntityManagerFactoryBean();
    entityManagerFactoryBean.setDataSource(dataSource);
    entityManagerFactoryBean.setPackagesToScan("");
    entityManagerFactoryBean.setJpaProperties(properties());
    entityManagerFactoryBean.setJpaVendorAdapter(new HibernateJpaVendorAdapter());
    return entityManagerFactoryBean;
}

private Properties properties() {
    Properties properties = new Properties();
    properties.put("hibernate.show_sql", "true");
    properties.put("hibernate.format_sql", "true");
    return properties;
}

更新

我有一个类似于你的配置类，但是由于我正在升级到Spring Boot，我已经删除了该类并将所有配置移动到application.properties文件中。我的配置如下：

#DataSource
spring.datasource.driver-class-name=org.postgresql.Driver
spring.datasource.url=jdbc:postgresql://localhost:5432/mydb
spring.datasource.username=postgres
spring.datasource.password=123456

#Hibernate
spring.jpa.properties.hibernate.show_sql=true
spring.jpa.properties.hibernate.format_sql=true
spring.jpa.properties.hibernate.jdbc.batch_size=10
spring.jpa.properties.hibernate.id.new_generator_mappings=true

spring.jpa.properties.hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect
spring.jpa.properties.hibernate.current_session_context_class=org.springframework.orm.hibernate5.SpringSessionContext

- Wilder Valera

---

你比我多了一些东西（方言或会话上下文），但它们是否与问题有关？方言不是，它由Spring自动发现（我尝试明确指定它，以防万一，但没有改变任何东西）。 - François Dupire

Answer 3

由于您提供的代码似乎不够充分，我将尝试通过一些说明来调试此问题。

1. 保留我在第一个答案中给出的更改。

2. 确保您展示的属性文件实际上控制着记录器的配置。例如，更改输出格式并检查它是否按预期影响输出。

3. 找到Hibernate中相关的日志记录语句。在那里设置断点。调试直到找到丢弃日志语句的位置。将涉及的数据结构与您的配置进行比较，以了解出现了什么问题。

- Jens Schauder

---

我会尝试的 :-). 我之前没有提到，但将rootLogger的日志级别设置为TRACE确实添加了一些日志，但没有SQL查询的日志。 - François Dupire

我尝试在我的测试第一行设置断点，并在那里获取org.hibernate.SQL记录器。它似乎配置良好。我仍然会尝试在Hibernate类中获取日志记录语句，但这并不像看起来那么容易 :-) - François Dupire

我没有时间深入挖掘，也没有解决方案。但是考虑到你给了我这么多帮助，我决定奖励你这个问题的赏金 :-) - François Dupire

我终于弄清楚了发生了什么。我注意到在失败的测试中，日志中发出了SQL查询。通过微调我的log4j属性，我看到它们来自hibernate记录器，正如预期的那样。但是成功的操作没有发出日志。这是因为它们没有到达数据库。一切都发生在实体管理器内部，因此不需要SQL。现在我知道我只是有一个需要解决的H2数据库问题。再次感谢您的帮助。 - François Dupire