Activate SQL statements logging with Hibernate and Spring Data JPA

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.