Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unable to log in the 'stop' method of GlobalExtension #966

Open
rtretyak opened this Issue Jan 24, 2019 · 2 comments

Comments

Projects
None yet
2 participants
@rtretyak
Copy link

rtretyak commented Jan 24, 2019

Hi.
Please consider this extension:

import groovy.util.logging.Slf4j
import org.spockframework.runtime.extension.AbstractGlobalExtension

@Slf4j
class LogExtension extends AbstractGlobalExtension {

    @Override
    void start() {
        log.info "I'm always logged"
    }
    
    @Override
    void stop() {
        log.info "I'm logged sometimes"
        sleep(1000)
        log.info "I'm never logged"
    }
}

Problem:
The logging inside the 'stop' method is kind of broken. There seems to be some race condition, since the first log message in 'stop' will sometimes get logged (once in about 3 runs on my local machine), but any subsequent logs will never get logged. In debug inside 'stop', the 'log' instance reads PrivateConfig [loggerConfig=root, config=org.apache.logging.log4j.core.config.NullConfiguration@186eca4d, loggerConfigLevel=OFF, intLevel=0, logger=org.openkilda.functionaltests.extension.LogExtension:OFF in ffaa6af], which is different from what I get in the start or visitSpec methods (it reads a valid config and non-OFF log level). Problem also reproduces if I create the logger directly, without using the @Slf4j transformation.
I'm configuring logger via log4j2.xml config which is located under src/test/resources. All other logs across all my framework do work as expected.
Can somebody please point me to the reason of such behavior? How can I fix this? I want to perform some logging at the end of the test run.
Spock version is 1.2-groovy-2.5, Groovy 2.5.3, log4j-slf4j-impl 2.10.0

@leonard84

This comment has been minimized.

Copy link
Member

leonard84 commented Mar 4, 2019

The stop method is currently run as a JVM shutown hook, this means that other system that also register a shutdown hook may cleanup their resources in parallel to your code. My guess is that is what is happening here. What happens if you are using System.out.println?
With Spock 2.0 we can use the new hooks provided by the JUnit Plattform to run before the JVM is shutting down, but JUnit 4 simply doesn't provide this extensibility.

@rtretyak

This comment has been minimized.

Copy link
Author

rtretyak commented Mar 5, 2019

I'm able to do println with no issues inside stop.
We've gone with some other solution to achieve what was planned, so this is not a blocker (at least for me). Looking forward to 2.0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.