JaCoCo Maven plugin reports code coverage inconsistently for Spring boot method marked as PreDestroy

[Ashley Breen]

Hi,

I have a Spring boot project that I am trying to generate code coverage for.

I found that the code coverage percentage reported goes up and down when running code coverage multiple times. 

When I investigated further, noticed that a method in my Spring component that is annotated with @PreDestroy is sometimes partly covered, sometimes not at all (see attached image)

@PreDestroy

public void save() {

LOGGER.debug("Repository.save() called");

LOGGER.debug("Repository.save() called 1");

LOGGER.debug("Repository.save() called 2");

if (null == _items)

return;

LOGGER.debug("Repository.save() called 3");

try{

   LOGGER.debug("Repository.save() called 4");

ObjectMapper mapper = new ObjectMapper();

LOGGER.debug("Repository.save() called 5");

mapper.writeValue(new File(_registrationFileName), _items);

LOGGER.debug("Repository.save() called 6");

   

} catch (Exception ex) {

   LOGGER.debug("Repository.save() called 7");

LOGGER.error(ex.getMessage());

LOGGER.debug("Repository.save() called 8");

LOGGER.error(ex.getStackTrace().toString());

LOGGER.debug("Repository.save() called 9");

}

LOGGER.debug("Repository.save() called 10");

}

When I add log statements to check if the method is executed to the end, I can see the log statements in the console in STS(Eclipse) but the code is reported as not covered (or one or 2 lines are covered).

The console also reports that the PreDestroy method is being executed on Thread-4, not the main thread.

2017-09-25 09:36:07.962  INFO 19780 --- [           main] .o.R.RegistrationServiceApplicationTests : Started RegistrationServiceApplicationTests in 4.615 seconds (JVM running for 7.177)

2017-09-25 09:36:08.110  INFO 19780 --- [       Thread-4] o.s.w.c.s.GenericWebApplicationContext   : Closing org.springframework.web.context.support.GenericWebApplicationContext@4bf8b77: startup date [Mon Sep 25 09:36:04 BST 2017]; root of context hierarchy

2017-09-25 09:36:08.370 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called

2017-09-25 09:36:08.371 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 1

2017-09-25 09:36:08.371 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 2

2017-09-25 09:36:08.371 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 3

2017-09-25 09:36:08.371 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 4

2017-09-25 09:36:08.371 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 5

2017-09-25 09:36:08.426 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 6

2017-09-25 09:36:08.426 DEBUG 19780 --- [       Thread-4] c.n.o.R.repository.Repository            : Repository.save() called 10

What settings am I missing to make JaCoCo include this method in it's code coverage calculations?

I am using JaCoCo plugin version 0.7.9, Maven 3.3.9, Spring 4.3.8.

I see the same inconsistent results when I run from the command line.

Thanks,

Ashley

[Marc Hoffmann]

Hi Ashley,

can you please identify the calling context of the save() method?

My wild guess is that it is called within JVM shutdown. By default JaCoCo also writes execution data in a shutdown thread. In this case it is not deterministic which is executed first.

Regards,
-marc

--
You received this message because you are subscribed to the Google Groups "JaCoCo and EclEmma Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jacoco+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jacoco/22153d9d-9614-450c-9599-77b694cf1098%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

 

[Ashley Breen]

Thanks for your reply Marc.

Yes, you're right - when I look at the call stack (see attachment) during debug of the Save() method, the first call in the stack is in AbstractApplicationContext::run() which is running the JVM shutdown hook:

/**

* Register a shutdown hook with the JVM runtime, closing this context

* on JVM shutdown unless it has already been closed at that time.

* <p>Delegates to {@code doClose()} for the actual closing procedure.

* @see Runtime#addShutdownHook

* @see #close()

* @see #doClose()

*/

@Override

public void registerShutdownHook() {

if (this.shutdownHook == null) {

// No shutdown hook registered yet.

this.shutdownHook = new Thread() {

@Override

public void run() {

synchronized (startupShutdownMonitor) {

doClose();

}

}

};

Runtime.getRuntime().addShutdownHook(this.shutdownHook);

}

}

Explains why I was seeing either no coverage or two lines covered for the Save() method.

Thanks,

Ashley

[Ashley Breen]

And I guess the only way round the issue is to set dumpOnExit to false and retrieve the coverage data remotely or via the API....?

[Evgeny Mandrikov]

Hi,

On Tuesday, September 26, 2017 at 10:41:11 AM UTC+2, Ashley Breen wrote:

And I guess the only way round the issue is to set dumpOnExit to false and retrieve the coverage data remotely or via the API....?

I guess that might be simpler to close context explicitly - https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/context/support/AbstractApplicationContext.html#close--