'Non clean shutdown detected' even though shutdown() method gets called

[wujek]

HI. Here is my code to initialize the database:

    @Provides

    @Singleton

    GraphDatabaseService graphDatabaseService(@Named("mino.db.path") String dbPath) {

        final GraphDatabaseService graphDb = new GraphDatabaseFactory().

                newEmbeddedDatabaseBuilder(dbPath).

                newGraphDatabase();

        getRuntime().addShutdownHook(new Thread() {

            @Override

            public void run() {

                graphDb.shutdown();

            }

        });

        return graphDb;

    }

This is a google-guice module that is used in a wicket application deployed on tomcat 7.0.x. When I do remote debugging and put a breakpoint in the graphDb.shutdown() line, when I stop tomcat this line gets called as the breakpoint gets hit and I can debug deeper. However, I see this each time I start my applicaton anew:

Non clean shutdown detected on log [/tmp/neo4j/nioneo_logical.log.1]. Recovery started ...

...

XaResourceManager[/tmp/neo4j/nioneo_logical.log] recovery completed.

Recovery on log [/tmp/neo4j/nioneo_logical.log.1] completed.

Does anybody know why this is happening?

wujek

[杨军]

public class Neo4jServletListener implements ServletContextListener {

    public static final String NEO4J_PATH = "neo4j-path";
    public static final String CONFIG_PATH = "config-path";
    private static final Logger logger = LoggerFactory.getLogger(Neo4jServletListener.class);

    @Override
    public void contextInitialized(ServletContextEvent sce) {
        String neo4jPath = sce.getServletContext().getInitParameter(NEO4J_PATH);
        String configPath = sce.getServletContext().getInitParameter(CONFIG_PATH);
        logger.info(neo4jPath);
        Neo4jUtils.init(neo4jPath, configPath);
    }

    @Override
    public void contextDestroyed(ServletContextEvent sce) {
        Neo4jUtils.shutdown();
    }
}

at web.xml

    <context-param>
        <param-name>neo4j-path</param-name>
        <param-value>/export/neo4j.spatial/db</param-value>
    </context-param>
    <context-param>
        <param-name>config-path</param-name>
        <param-value>/export/neo4j.spatial/config</param-value>
    </context-param>
    <listener>
        <description>Neo4j ServletContextListener</description>
        <listener-class>org.demo.spatial.web.Neo4jServletListener</listener-class>
    </listener>

2012/10/23 wujek <wujek....@gmail.com>

wujek

--
 
 

--

Best regards,
yang jun
Tel:  028-85126877
Mob:  18608027881 <mailto:yangjun...@gmail.com>

Chat: yangjun...@gmail.com(gtalk)

[Wujek Srujek]

HI. Thanks for your answer. I know I can do it in a context listener, but for various reasons I would like not to if possible, and I would also like to know why it doesn't work the way I did it, especially when such code is shown in the official documentation (registering the shutdown hook) - the code is executed, after all. I checked it and the 'lock' file in the directory is never removed...

wujek

--
 
 

[Michael Hunger]

Perhaps your startup code is executed again? (i.e. if you use a singleton or such and then request the db-instance again)

Michael

--
 
 

[Wujek Srujek]

Hi. No, the instance is created only once (it's a guice Singleton), and destroyed only when the JVM goes down, with the hook (it's not just words, I've just debugged it). Also, the logs would say that the database is started again, I guess.

Would you be interested in getting a tiny contrived application that shows this behavior to maybe take a peek what is going on (I could prepare it later today)?

wujek

--
 
 

[Wujek Srujek]

I can see this at the end of the neo_dir/messages.log after tomcat has been shut down:

...

2012-10-23 10:42:39,931 DEBUG [neo4j]: Started - database is now available

2012-10-23 10:42:39,934 DEBUG [neo4j]: GC Monitor started.

2012-10-23 10:44:23,427 DEBUG [neo4j]: Stopping - database is now unavailable

2012-10-23 10:44:23,429 DEBUG [neo4j.txmanager]: TM shutting down

2012-10-23 10:44:23,434 DEBUG [neo4j.diagnostics]: --- SHUTDOWN diagnostics START ---

2012-10-23 10:44:23,434 DEBUG [neo4j.diagnostics]: --- SHUTDOWN diagnostics END ---

but neo_dir/lock is still there.

However, in tomcat logs I can see this (I already posted a question about this here: https://groups.google.com/forum/?fromgroups=#!topic/neo4j/ruLdcTAjm9o):

Exception in thread "Thread-3" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy

at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:125)

at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:447)

at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403)

at ch.qos.logback.classic.Logger.error(Logger.java:566)

at org.neo4j.kernel.logging.LogbackService$Slf4jStringLogger.logMessage(LogbackService.java:161)

at org.neo4j.kernel.impl.util.StringLogger.logMessage(StringLogger.java:149)

at org.neo4j.kernel.InternalAbstractGraphDatabase.shutdown(InternalAbstractGraphDatabase.java:573)

at de.mino.wiring.guice.MinoModule$1.run(MinoModule.java:113)

Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy

at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1714)

at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1559)

... 8 more

Which means the shutdown method throws an exception somewhere and hence it is never really shut down correctly.

I am using logback-classic-1.0.7.jar and as mentioned in the other post, the jars and the classes are on the classpath. I noticed neo depends on logback-1.0 which is old and also probably on some older version of slf4j. logback-1.0 is optional in neo4j pom.xml and is not included in the war. I wonder what is going here.

wujek

[wujek]

So the line:

at org.neo4j.kernel.InternalAbstractGraphDatabase.shutdown(InternalAbstractGraphDatabase.java:573)

is actually a catch block that catches a LifecycleException and logs it. In this case, the exception is:

message: Failed to transition org.neo4j.kernel.impl.transaction.XaDataSourceManager@5e0e9df5 from STOPPED to SHUTTING_DOWN

cause: java.lang.NoClassDefFoundError: org/neo4j/index/impl/lucene/IndexReference

But neo4-lucene-index-1.8.jar is on the classpath, as otherwise the application works fine and it does use indexing with lucene. The next thing that happens is that a logback class cannot be found so this exception cannot be logged. I guess this will be connected with the fact that tomcat is shutting down and maybe the webapp classloader is already removed or something.

wujek

wujek

--

Mob:  18608027881 <mailto:yangjun.chengdu@gmail.com>




Chat: yangjun...@gmail.com(gtalk)

--
 
 

--
 
 

--
 
 

[Michael Hunger]

Perhaps the classpath is no longer available after the tomcat shutdown (if tomcat has already killed its classloaders)? So that it cannot find the class anymore.

Is neo4j a part of your war in this case? Then the stuff will have been unloaded when the jvm is about to quit.

Just guessing.

--
 
 

[Wujek Srujek]

Hi. I'm guessing it is something like this. Yes, neo4j is in WEB-INF/lib, as all the other jars. I am currently working on simple code to see that classloaders are used and what can and what cannot be loaded with which CL ;d If I know more, I will come back and report.

Thanks for your interest.

wujek

--
 
 

[wujek]

Ok, so I did some more debugging and here is what I found out - when the shutdown hook is executed, the tomcat's WebAppClassLoader for my webapp still exists (as the class containing the code being called was loaded with it and keeps a hard reference, and live threads, what the hook really is, are GC-roots so are not collectable), but all its fields (most importantly in this case, repositoryUrls - this is where URLs for jars form WEB-INF/lib are kept) are empty, contrary to when I debug the application while tomcat runs normally. This means, IndexReference is probably the first class that is in WEB-INF/lib that is used during shutdown that hasn't been loaded for the application yet - and the WebAppClassLoader tries to load it, and fails, tries to load the ThrowableProxy to log the exception, and it also fails - the webapp CL is empty and cannot load anything. It's parent is StandardClassLoader which has the tomcat/lib jars, then there is the system class loader, extensions CL, and bootstrap - none of these can load the classes and hence the failure.

When I force loading this class with Class.forName("org.neo4j.index.impl.lucene.IndexReference"), which uses the caller CL, which is the WebAppClassLoader, all works as expected,

This basically means that the shutdown hook trick is not usable for web applications, at least on tomcat 7.0.x.

[Michael Hunger]

Or you have to make the neo4j dependencies available to the tomcat root/boot classpath.

Michael

> --
>
>

[Wujek Srujek]

Correct, but this would mean I need to 'patch' all tomcats that my application is supposed to run on, which is not a good idea I think - first, I can't just hand a working war; second - a memleak, see below. I will just do it 'the right way', i.e., shutdown the database in a ServletContextListener. It will require slight redesign but no biggie. I had hoped I could do it with the shutdown hook, as I could just register the hook in the guice module and it would work no matter how my backend services are used (webapp, ejb, JavaSE app, whatever), but this just doesn't work.

Actually, this shutdown hook idea for a webapp that I had and tried to implement is completely broken - suppose it works; if my application is undeployed from the server, but the server itself is not shut down, the database will not be shut down until the server JVM goes down - as I have no ServletContextListener.contextDestroyed. Nice. I've just created a nasty memory leak, as as said, the shutdown hook thread is a GC root, it keeps a reference to the WebappCL that loaded it, which in turn keeps references to all classes that it ever loaded. Redeploy the app a few times and it will result in a OOME: PermSpace rather sooner than later. Stupid me.

I actually debugged it a little more with tomcat sources and all things said previously are correct - when tomcat stops, it stops all internal services, and in the depths, each WebappCL is also a service, and all its fields get nulled out and eventually the CL itself gets nulled out. However, in my 'clever' idea, this nulling out doesn't help the GC. I really hope others are smarter and don't try to do this, and if they do, I hope this thread will come in handy...

wujek

--