Dovahkiin vas Normandy Dovahkiin vas Normandy - 2 months ago 14
Java Question

When Is My Business Code Actually Being Executed?

I got a Spring Boot app. It's running as such:

@SpringBootApplication
public class MyBooty implements CommandLineRunner {

public static void main(String[] args) {
SpringApplication.run(MyBooty.class, args);
}

public void run(String... args) throws Exception {
SomeClass someClass = new SomeClass(...);
someClass.doStuff();
System.out.println("Why Am I appearing Before \"Started In\" log line?");
}


Does what I need. But I noticed this line in the output:
Started MyBooty in 17.594 seconds (JVM running for 18.206)
, which was printed after some of my console output.

This made me think my code was actually executing before the app was actually initialized. So I did some research found this blog post and then set up a new class as such:

@Component
public class ApplicationStartup implements ApplicationListener<ApplicationReadyEvent>{

public void onApplicationEvent(ApplicationReadyEvent event) {
SomeClass someClass = new SomeClass(...);
SomeClass.doStuff();
return;
}

}


Which supposedly executes after after application startup. Well, I still see the
Started app in...
output after my output again.

So, concept check. Are things working as intended and I'm just being naive? Or is there maybe something missing? If someone could knowledge share on the topic that would be appreciated.

Again, my code runs and does exactly what I need it to, but I just want to make sure I'm using/taking advantage of Spring Boot properly.

In case it's unclear what I'm asking, I'm asking Why does the "Started App in X seconds" message appear after my output? I ask this because I simply found it confusing that it said the app was started after my business code had ALREADY ran. This question is a conceptual question about how spring boot starts up.

Edit: Console Output

. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v1.3.2.RELEASE)

2016-09-23 17:44:56.598 INFO 1004 --- [ main] o.b.p.MyBooty : Starting MyBooty on ********* with PID **** (C:\...\MyBooty)
:
:
:
2016-09-23 17:44:59.152 INFO 1004 --- [ main] o.apache.catalina.core.StandardService : Starting service Tomcat
2016-09-23 17:44:59.154 INFO 1004 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.0.30
2016-09-23 17:44:59.725 INFO 1004 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2016-09-23 17:44:59.725 INFO 1004 --- [ost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 3074 ms
2016-09-23 17:45:00.228 INFO 1004 --- [ost-startStop-1] o.s.b.c.e.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
2016-09-23 17:45:00.234 INFO 1004 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
2016-09-23 17:45:00.234 INFO 1004 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2016-09-23 17:45:00.234 INFO 1004 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2016-09-23 17:45:00.234 INFO 1004 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
2016-09-23 17:45:00.824 INFO 1004 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@453da22c: startup date [Fri Sep 23 17:44:56 CDT 2016]; root of context hierarchy
2016-09-23 17:45:00.901 INFO 1004 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2016-09-23 17:45:00.902 INFO 1004 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2016-09-23 17:45:00.925 INFO 1004 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-09-23 17:45:00.925 INFO 1004 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-09-23 17:45:00.962 INFO 1004 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-09-23 17:45:01.136 INFO 1004 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2016-09-23 17:45:01.215 INFO 1004 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
Why Am I appearing Before "Started In" log line?
2016-09-23 17:45:17.063 INFO 1004 --- [ main] o.b.p.MyBooty : Started MyBooty in 20.814 seconds (JVM running for 23.279) <----- Why is this after my output?
2016-09-23 17:45:22.675 INFO 1004 --- [)-10.168.50.106] inMXBeanRegistrar$SpringApplicationAdmin : Application shutdown requested.
2016-09-23 17:45:22.676 INFO 1004 --- [)-10.168.50.106] ationConfigEmbeddedWebApplicationContext : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@453da22c: startup date [Fri Sep 23 17:44:56 CDT 2016]; root of context hierarchy
2016-09-23 17:45:22.678 INFO 1004 --- [)-10.168.50.106] o.s.j.e.a.AnnotationMBeanExporter : Unregistering JMX-exposed beans on shutdown

Answer

You class is annotated with @SpringBootApplication, which makes it automatically register as a Spring Bean.

The SpringApplication run(Object source, String... args) method you are calling ends up calling run(String... args).

The run() method calls the afterRefresh() method right before it logs the "Started ..." message, and afterRefresh() will call the run() method of any registered ApplicationRunner and CommandLineRunner beans.

Or, as the documentation says it:

If you need to run some specific code once the SpringApplication has started, you can implement the ApplicationRunner or CommandLineRunner interfaces. Both interfaces work in the same way and offer a single run method which will be called just before SpringApplication.run(…​) completes.