使用 Hibernate 和 Spring Data JPA 激活 SQL 语句日志记录答案

【问题标题】：Activate SQL statements logging with Hibernate and Spring Data JPA使用 Hibernate 和 Spring Data JPA 激活 SQL 语句日志记录
【发布时间】：2018-06-07 03:21:37
【问题描述】：

我有一个使用 Hibernate 作为提供者的 Spring Data JPA 存储库。我想记录 SQL 语句，但我做不到。我尝试了各种解决方案：

在我的 HibernateJpaVendorAdapter 中将 showSql 设置为 true
将 log4j.logger.org.hibernate.SQL=DEBUG 添加到我的 log4j.properties 文件中（值得一提的是，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 日志记录配置之间是否存在某种不兼容？

编辑：我尝试了 cmets 中提出的两种解决方案，但都没有奏效。我还尝试更改我正在使用的数据库（H2 for HSQL）或指定 Hibernate 方言，但这不起作用。事实上，在使用 Spring 时，某些数据库会自动找到 Hibernate 方言。

编辑 2：我试图将 rootLogger 的日志记录级别更改为 TRACE。我还尝试明确指定附加程序的阈值。最后，我尝试使用 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 属性，我发现它们来自休眠记录器，正如预期的那样。

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

【问题讨论】：

试试在 porperties 文件中添加logging.level.org.hibernate.SQL=DEBUG logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE 看看？
您说log4j.logger.org.hibernate=INFO 添加了一些日志记录，但log4j.logger.org.hibernate.SQL=DEBUG 没有。你试过...log4j.logger.org.hibernate=DEBUG吗？还是上面有错字？
@AhmedRaaj ：这些属性必须放在 Spring 属性文件中（如 application.properties）。我没有，我没有使用 Spring Boot。我尝试将 log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=‌TRACE 添加到我的 log4j.properties 文件中，但由于此记录器的目标是显示绑定参数，因此没有效果。
@dimwittedanimal : 没有错字:-)。我提到 log4j.logger.org.hibernate 是为了指出它对日志记录有影响，尽管另一个没有（我觉得很奇怪）。我尝试将 DEBUG 级别设置为以前的记录器，它显示了更多信息，但仍然没有查询（因为这不是预期的工作）。

标签： java hibernate jpa logging spring-data-jpa

【解决方案1】：

替换：

log4j.rootLogger=INFO, stdout

有

log4j.rootLogger=TRACE, stdout

还有可能添加

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

如果你也想要绑定变量的值。

您的日志记录配置良好，但您的 appender 仅获取 INFO 并且 SQL 语句已记录在 DEBUG

【讨论】：

这似乎确实合法 :-)。今晚我会试试，结果回来给你！
我刚试过，但没用。考虑一下这是预期的，因为它只更改了根记录器的日志记录级别，而不是附加程序的阈值（我也尝试顺便更改但也没有工作）。不过感谢您的尝试。
不确定附加程序的阈值是什么意思。 appender 没有，除非通过它对根记录器的配置。
appender 有一个阈值参数，独立于 loggers 日志级别。它允许日志从一个 appender 到另一个不同，而无需更改 loggers 的日志级别。例如，如果您想在控制台中记录所有内容，但只在文件中记录错误，您可以使用不同的阈值配置附加程序，同时不触及记录器配置。
好的，现在知道了。

【解决方案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

【讨论】：

你比我有一些东西（方言或会话上下文），但这些与问题有关吗？方言不是，它是由 Spring 自动找到的（我试图明确指定它以防万一，没有改变）。

【解决方案3】：

由于查看您提供的代码似乎并没有减少它，我将尝试使用一些说明如何调试它。

保留我在第一个答案中给出的更改。
确保您显示的属性文件实际上控制了记录器配置。对于此更改，例如，输出格式并检查它是否按预期影响输出。
在 Hibernate 中查找相关的日志记录语句。在那里放置一个断点。调试直到找到日志语句被丢弃的地方。比较与您的配置相关的数据结构以了解问题所在。

【讨论】：

我会试试的:-)。我之前没有提到它，但是将 rootLogger 的日志记录级别设置为 TRACE 确实添加了一些日志，但没有添加 SQL 查询。
我试图在我的测试的第一行设置一个断点并在那里获取 org.hibernate.SQL 记录器。它似乎配置得很好。我仍然会尝试在休眠类中获取日志语句，但这并不像看起来那么容易:-)
我没有时间进一步挖掘，我仍然没有解决方案。但是考虑到你给我的帮助，我决定奖励你这个问题的赏金:-)
我终于弄清楚发生了什么。我注意到在失败的测试中，在日志中发出了 SQL 查询。通过稍微调整我的 log4j 属性，我看到它们来自休眠记录器，正如预期的那样。但是成功的操作并没有发出日志。那是因为他们没有到达数据库。一切都发生在实体管理器中，因此不需要 SQL。现在我知道我的 H2 数据库有问题需要解决。再次感谢您的帮助。