2.3.7 data.sql are not any longer exectued

[leomayer]

After upgrading from 2.3.6. to 2.3.7. the data.sql scripts are not any longer executed when starting test runs.

The scripts are located in src/test/resources

I've checked this and since I need to load data into my own properties I did it with

public class ApplicationInitDocumat implements ApplicationListener<ContextRefreshedEvent> {

	@Autowired
	private MyDBController consistentChecker;
	/**
	 * Listen to startup/context refresh events
	 */
	@Override
	public void onApplicationEvent(ContextRefreshedEvent event) {
        // failed to load data  from database which is loaded via data.sql

[wilkinsona]

The scripts are loaded from the classpath so it should make no difference if they're in src/test/resources or src/main/resources as long as the resources in those locations have been placed on the classpath by whatever you're using to run your tests.

We have numerous integration and smoke tests that rely on schema.sql and data.sql files being executed and they are all passing so it's not clear to me what may be causing your problem. If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

[leomayer]

I tried to reproduce the issue with a simple project but didn't succeed. I digged little bit deeper and turned on the log level for our real project. I attach the logs to the issue. It seems like the data.sql are exectuted but they are not fetched from the DB. Data which was inserted and could be looked for:

• COUNTRY
• PROPERTY_EXTENSION
  boot2.3.6.log.gz
  boot2.3.7.log.gz

Remark: The logs are up to the point where an JPARepostiory.findAll() was executed. Immediately afterwards a breakpoint was set and the logs ended. While in 2.3.6 the findAll() returned a list of 8 items the 2.3.7 version returned 0 items. Therefore I concluded that the data.sql were not executed. But perhaps the conclusion was too quick and the root cause is somewhere else.

[wilkinsona]

Thanks for the logs. Unfortunately, there's nothing in them that's an immediately obvious reason for the different behaviour. I'm not sure what logging you enabled, but the output doesn't seem to include any Spring Framework or Spring Boot code. For example, I'd expect to see logging from org.springframework.jdbc.datasource.init.ScriptUtils but didn't see any in either file. Could you change you logging configuration to include org.springframework.jdbc to confirm whether or not the files are being processed?

I tried to reproduce the issue with a simple project but didn't succeed

This would suggest that the problem's somehow specific to your environment or to your main application's dependencies. The former will make it hard for us to diagnose the problem. The latter will too without a sample with which we can reproduce the problem.

[leomayer]

Sorry, I have no clue what kind of options I should enable. I did already on

logging:
  level:
    root: DEBUG

Since they are not sufficient plz advice which one to set.

[wilkinsona]

That's a strange one too. Root-level debug logging should have been sufficient. I suspect you may have some configuration elsewhere that's overriding that configuration for all but Hibernate and handful of other loggers. Unfortunately, I can't tell if that's definitely the case without knowing more about your application and its configuration. I think we've reached the point where we need a sample that reproduces the problem to make some progress.

[leomayer]

The config of the logging is quite strange. The root level is not applied to the sub level - don't know if this is another issue? Anyway config like this included the information you've requested.

logging:
  level:
    root: DEBUG
    org:
      hibernate: 
        SQL: DEBUG
        type.descriptor.sql.BasicBinder: TRACE
      springframework: DEBUG

If you need other log levels (or format of the output) than plz advice.

boot.2.3.7_jdbc_ROOT.log.gz
boot.2.3.6_jdbc_ROOT.log.gz

As mentioned already. The easiest way to find the diff in the log is by search for PROPERTY_EXTENSION

[wilkinsona]

Thanks. On 2.3.6 the data.sql script was found in target/test-classes:

09:10:22.671 DEBUG - [  task-2] o.s.jdbc.datasource.init.ScriptUtils    :572-Executing SQL script from URL [file:/home.local/lw/workspace-documat/documat-backend/target/test-classes/data.sql]

There's no such log line with 2.3.7. This gives us something to focus on.

The thread being task-2 is interesting and is a notable difference to the 2.3.7 log where everything happens on main. That's due to #24249 but shouldn't affect the discovery of data.sql scripts. I think we can ignore this for now at least.

As far as I can tell from the logs provided, the data.sql script isn't on the classpath, i.e. it isn't in target/test-classes when the application is run. Without a sample to enable me to investigate, you're going to have to do so yourself. If I was you, I would begin that investigation by debugging the application on Spring Boot 2.3.7 with a breakpoint on org.springframework.boot.autoconfigure.jdbc.DataSourceInitializer.getResources(String, List<String>, boolean). Stepping into the work performed by SortedResourcesFactoryBean and its ResourcePatternResolver should let you see what's going on. TRACE level logging for org.springframework.core.io.support may also be informative.

[leomayer]

Just a few points from my side:

• we have several projects which are configured similar - i.e. we have some sub-projects which have some configuration and tests
• up till 2.3.6 we have set up our tests according to what is available in docu and on several platforms.
• I highly suspect Add note about change in processing order of configuration files to release notes #24497 as one of the prime candidates for the root cause - either this or another way. I wouldn't treat this just as documentary - more as a breaking change.
• I highly assume that other projects in other (big) companies structured their projects similarly and therefore I would expect that code running with 2.3.6 is still working in later versions as well as in 2.4.x

End of my general statement.

Focusing of the issue: Please provide next time a specific yml configuration for details you are looking for. I'm still not sure if I configured the logs properly.

You mentioned I should set a breakpoint in 2.3.7 - I did so. It stopped as well in 2.3.6. for the DefaultListableBeanFactory. But the screenshot below is only in 2.3.6 available.

boot.2.3.6_jdbc_core.log.gz
boot.2.3.7_jdbc_core.log.gz

[leomayer]

I did little bit of debugging by myself and set a breakpoint in org.springframework.context.support.AbstractApplicationContext line 361:

@Override
public void publishEvent(ApplicationEvent event) {
  publishEvent(event, null);
}

for event I get

• 2.3.7
  org.springframework.context.event.ContextRefreshedEvent[source=org.springframework.web.context.support.GenericWebApplicationContext@10fbbdb, started on Thu Jan 14 12:56:38 CET 2021]

• 2.3.6
  org.springframework.context.event.ContextRefreshedEvent[source=org.springframework.web.context.support.GenericWebApplicationContext@57a2ed35, started on Thu Jan 14 12:59:35 CET 2021]

AND
org.springframework.boot.autoconfigure.jdbc.DataSourceSchemaCreatedEvent[source=HikariDataSource (HikariPool-1)]

Digging further into org.springframework.orm.jpa.AbstractEntityManagerFactoryBean#buildNativeEntityManagerFactory

  JpaVendorAdapter jpaVendorAdapter = getJpaVendorAdapter();
  if (jpaVendorAdapter != null) {
	jpaVendorAdapter.postProcessEntityManagerFactory(emf);
  }

• 2.3.7 jpaVendorAdapter=org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter@6f4d2294 ==>

AbstractJpaVendorAdapter
@Override
public void postProcessEntityManagerFactory(EntityManagerFactory emf) {
}

• 2.3.6 jpaVendorAdapter=org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher$DataSourceSchemaCreatedPublisher@53c613f7 with

org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher

@Override
public void postProcessEntityManagerFactory(EntityManagerFactory entityManagerFactory) {
	this.delegate.postProcessEntityManagerFactory(entityManagerFactory);
	AsyncTaskExecutor bootstrapExecutor = this.factoryBean.getBootstrapExecutor();
	if (bootstrapExecutor != null) {
		DataSourceInitializedPublisher.this.initializationCompletionListener.dataSourceInitialization = bootstrapExecutor
				.submit(() -> DataSourceInitializedPublisher.this.publishEventIfRequired(this.factoryBean,
						entityManagerFactory));
	}
}

For the sake of completeness I included as well the log files with the following settings.

logging:
  level:
    #root: DEBUG
    org:
      hibernate: 
        SQL: DEBUG
        type.descriptor.sql.BasicBinder: TRACE
      springframework: 
        jdbc: DEBUG
        core:
          io: TRACE
        orm: TRACE  

boot.2.3.7.ormTRACE.log.gz
boot.2.3.6.ormTRACE.log.gz

[wilkinsona]

Thanks.

#24497 isn't relevant here as it's regarding a change made in 2.4.x and this issue is occurring in 2.3.7. Let's keep this issue focussed on a single problem please.

The missing DataSourceSchemaCreatedEvent is interesting. It should be published as a result of the LocalContainerEntityManagerFactoryBean being created. Here's a stack trace captured in my IDE's debugger of when this occurs:

Thread [main] (Suspended)	
	owns: ConcurrentHashMap<K,V>  (id=125)	
	owns: Object  (id=133)	
	AnnotationConfigServletWebServerApplicationContext(AbstractApplicationContext).publishEvent(ApplicationEvent) line: 361	
	DataSourceInitializedPublisher.publishEventIfRequired(LocalContainerEntityManagerFactoryBean, EntityManagerFactory) line: 110	
	DataSourceInitializedPublisher.postProcessAfterInitialization(Object, String) line: 101	
	DefaultListableBeanFactory(AbstractAutowireCapableBeanFactory).applyBeanPostProcessorsAfterInitialization(Object, String) line: 430	
	DefaultListableBeanFactory(AbstractAutowireCapableBeanFactory).initializeBean(String, Object, RootBeanDefinition) line: 1798	
	DefaultListableBeanFactory(AbstractAutowireCapableBeanFactory).doCreateBean(String, RootBeanDefinition, Object[]) line: 594	
	DefaultListableBeanFactory(AbstractAutowireCapableBeanFactory).createBean(String, RootBeanDefinition, Object[]) line: 516	
	DefaultListableBeanFactory(AbstractBeanFactory).lambda$doGetBean$0(String, RootBeanDefinition, Object[]) line: 324	
	409598930.getObject() line: not available	
	DefaultListableBeanFactory(DefaultSingletonBeanRegistry).getSingleton(String, ObjectFactory<?>) line: 234	
	DefaultListableBeanFactory(AbstractBeanFactory).doGetBean(String, Class<T>, Object[], boolean) line: 322	
	DefaultListableBeanFactory(AbstractBeanFactory).getBean(String) line: 202	
	AnnotationConfigServletWebServerApplicationContext(AbstractApplicationContext).getBean(String) line: 1109	
	AnnotationConfigServletWebServerApplicationContext(AbstractApplicationContext).finishBeanFactoryInitialization(ConfigurableListableBeanFactory) line: 869	
	AnnotationConfigServletWebServerApplicationContext(AbstractApplicationContext).refresh() line: 551	
	AnnotationConfigServletWebServerApplicationContext(ServletWebServerApplicationContext).refresh() line: 143	
	SpringApplication.refresh(ConfigurableApplicationContext) line: 758	
	SpringApplication.refresh(ApplicationContext) line: 750	
	SpringApplication.refreshContext(ConfigurableApplicationContext) line: 405	
	SpringApplication.run(String...) line: 315	
	SpringApplication.run(Class<?>[], String[]) line: 1237	
	SpringApplication.run(Class<?>, String...) line: 1226	
	SampleDataJpaApplication.main(String[]) line: 26

Can you please use the debugger to determine when the event hasn't been published?

[leomayer]

I don't understand what you are looking for. As mentioned before - the HibernateJpaVendorAdapter has no method included. Therefore no Event is created. Hmmm... I guess I was tooo quick and already answered your question :-)

[wilkinsona]

The event's published in a few different places depending on what sort of initialization is being used. The place that's of interest in this case is the one shown in the stack above:

spring-boot/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/orm/jpa/DataSourceInitializedPublisher.java

Lines 98 to 102 in aa15a1d

	if (bean instanceof LocalContainerEntityManagerFactoryBean && this.schemaCreatedPublisher == null) {
	LocalContainerEntityManagerFactoryBean factoryBean = (LocalContainerEntityManagerFactoryBean) bean;
	EntityManagerFactory entityManagerFactory = factoryBean.getNativeEntityManagerFactory();
	publishEventIfRequired(factoryBean, entityManagerFactory);
	}

This is the code in Spring Boot 2.3.7 and it's the call to publishEventIfRequired that should trigger the publication of the event.

[leomayer]

Sorry if I'm persistent - but I still guess ....

Well anyway.... In Spring Boot 2.3.7. I neither hit line 90, 93, 96 nor 99.

While in Spring Boot 2.3.6. I hit all of them - before I hit org.springframework.orm.jpa.AbstractEntityManagerFactoryBean#buildNativeEntityManagerFactory

So, what kind information you need next?

[wilkinsona]

That would suggest that the LocalContainerEntityManagerFactoryBean is being prematurely initialised such that it isn't eligible for post-processing by DataSourceInitializedPublisher. We'll need a sample that reproduces the problem to identify why that's the case. Alternatively, you could use the debugger with a breakpoint in org.springframework.boot.autoconfigure.orm.jpa.JpaBaseConfiguration.entityManagerFactory(EntityManagerFactoryBuilder) to see exactly when the bean is being created and step through its post-processing.

[leomayer]

Sorry, but I doubt that the JpaBaseConfiguration.entityManagerFactory is the proper spot. Since in 2.3.6 this is hit after org.springframework.orm.jpa.AbstractEntityManagerFactoryBean#buildNativeEntityManagerFactory is hit. But in 2.3.7. it is the other way around.

Why is the order changed from 2.3.6 ==> 2.3.7? Is this somehow related?

Yeah, a sample would be great - but I have honestly no clue what to include and what to provide.

[wilkinsona]

The ordering should not have changed. The entityManagerFactory @Bean method should create a LocalContainerEntityManagerFactoryBean and return it. This bean should then be initialised at which point afterPropertiesSet() is called on it and it then calls buildNativeEntityManagerFactory(). If buildNativeEntityManagerFactory() is being called before the entityManagerFactory @Bean method, the only explanation that I can think of is that you have multiple entity manager factories in your application. Furthermore, if org.springframework.boot.autoconfigure.orm.jpa.JpaBaseConfiguration.entityManagerFactory(EntityManagerFactoryBuilder) is still being called, then the additional entity manager factory must have been defined in an auto-configuration that runs after HibernateJpaAutoConfiguration, otherwise Boot's auto-configured entity manager factory should have backed off.

Unfortunately, I don't think I can justify spending any more time trying to help you based on the information that you're currently able to provide. The structure and components of an application are almost impossible to infer from log files alone. If you cannot provide a minimal sample that reproduces the problem, then perhaps you could provide access to the application itself via a private repository on GitHub or similar along with the steps to take to reproduce the problem?

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[spring-projects-issues]

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.