Activate SQL statements logging with Hibernate and Spring Data JPA

Question

I have a Spring Data JPA repository using Hibernate as provider. I would like to log SQL statements but I can't achieve that. I tried various solutions :

• Set showSql to true in my HibernateJpaVendorAdapter
• Add log4j.logger.org.hibernate.SQL=DEBUG to my log4j.properties file (it's worth mentioning that log4j.logger.org.hibernate=INFO did add some logging information but log4j.logger.org.hibernate.SQL=DEBUG didn't)

Here are my classes and configuration files:

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

Why is it that the previous solutions didn't work ? Is there some kind of incompatibility between Spring Data JPA and Hibernate SQL logging configuration ?

EDIT : I tried both solutions proposed in comments but none of them worked. I also tried to change the database I was using (H2 for HSQL) or to specify Hibernate dialect but that didn't work. As a matter of fact Hibernate dialect is automatically found for some databases when using Spring.

EDIT 2 : I tried to change logging level of the rootLogger to TRACE. I also try to specify a threshold for the appender explicitely. And finally I tried to add JpaProperties with showSql = true but none of them did the trick. I think that there is something really obvious to do that I'm missing to unlock the complete situation :-/

EDIT 3 : Calling the logger directly as in the following test did work. I became to wonder if there is a typo or something that prevent Hibernate to use the logger.

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

Here are the resulting logs:

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'

EDIT 3: I finally figured out what happen. I noticed that on failed tests SQL queries were issued in the logs. And by tuning a little bit my log4j properties I saw they came from hibernate logger, as expected.

But successful operations were not issuing logs. And that's because they don't reach the database. Everything happens within the entity manager and so no SQL is needed. Now I know that I just have a problem with my H2 database that I need to figure out.

Answer 1

Replace:

log4j.rootLogger=INFO, stdout

With

log4j.rootLogger=TRACE, stdout

And possibly add

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

If you want the values of bind variables as well.

You had your logging configured fine, but your appender was only picking up INFO and SQL statements are logged on DEBUG

Answer 2

Try with this:

@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;
}

UPDATE

I had a similar config class as yours, since I am update to spring boot I removed that class and moved all the config to the application.properties file. My config is:

#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