This discussion is archived
9 Replies Latest reply: May 31, 2013 7:05 AM by Linda Lee RSS

NPE in ConsoleRedirectHandler when reopening a entity store during redeploy

804877 Newbie
Currently Being Moderated
I'm developing a Web app that uses BDB JE on the server side to store data. I'm using BDB JE version 5.0.58 and Glassfish version 3.1.2.2 to host the Web app.

My problem is that when I re-deploy my Web app, I'm getting NullPointerExceptions in BDB's logging infrastructure. In particular, I'm seeing the following stack trace repeating thousands of times:

java.lang.NullPointerException
at com.sleepycat.je.utilint.ConsoleRedirectHandler.publish(ConsoleRedirectHandler.java:31)
at java.util.logging.Logger.log(Logger.java:565)
at java.util.logging.Logger.doLog(Logger.java:586)
at java.util.logging.Logger.log(Logger.java:609)
at com.sleepycat.je.utilint.LoggerUtils.logMsg(LoggerUtils.java:353)
at com.sleepycat.je.cleaner.UtilizationCalculator.getBestFile(UtilizationCalculator.java:512)
at com.sleepycat.je.cleaner.FileSelector.selectFileForCleaning(FileSelector.java:211)
at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:226)
at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)
at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:162)
at java.lang.Thread.run(Thread.java:722)

I'm using DPL and I'm closing the entity store and the environment when the Web app is destroyed by Glassfish. The stack traces start appearing as soon as I construct the new EntityStore when Glassfish re-loads the Web app.

I've tried re-creating this outside of Glassfish with no luck.

Has anyone encountered this problem? We've used this code for other Web apps and not seen this problem.
  • 1. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    Linda Lee Journeyer
    Currently Being Moderated
    Steve,

    We've not heard about it before, but the way I look at it, it seems like a static hashmap is null, which doesn't make a lot of sense. Presumably it's something about how Glassfish is initializing things?

    java.lang.NullPointerException
    at com.sleepycat.je.utilint.ConsoleRedirectHandler.publish(ConsoleRedirectHandler.java:31) it this line of code:
        public void publish(LogRecord record) {
            EnvironmentImpl envImpl = 
                LoggerUtils.envMap.get(Thread.currentThread());   
    It must be that LoggerUtils.envMap is null, but LoggerUtils.envMap is a static:
    public class LoggerUtils {
         ...
        static Map<Thread, EnvironmentImpl> envMap =
            new ConcurrentHashMap<Thread, EnvironmentImpl>();
    Does that give you any clues?

    Linda

    Edited by: Linda Lee on May 24, 2013 10:54 AM - formatting
  • 2. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    804877 Newbie
    Currently Being Moderated
    We pulled the JE source and got to that point and we couldn't figure out how that static member could be null either.

    We've used this code in other Web apps before, so we're not sure why this is happening this time when it hadn't before.

    I assume that Glassfish is messing with the logging subsystem (and possibly with the classloaders?), but as far as I understand Java, there shouldn't be a way for that member to be null, even in the constructor for that class.

    It's a weird one. Perhaps I'll ask in the glassfish forum.
  • 3. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    909806 Newbie
    Currently Being Moderated
    I haven't looked a this code specifically, but there are two ways this could be null:

    1) The variable isn't final, so something could be setting it to null subsequent to initialization.

    2) Since it's a static initializer, it will be null while earlier (depended-on) static initializers are running. One place I've seen this (involving logging code, actually): Class A logs inside a static initializer, and logging is configured to use a formatter which involves class B, and class B has a static dependency on class A.

    So that's all to say, look and see if you have any logging inside static initializers, and also check whether you have any fancy log formatters configured. Also this is the sort of problem that can come or go if you happen to touch classes in a different order, as the result of a seemingly unrelated code change.
  • 4. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    Linda Lee Journeyer
    Currently Being Moderated
    >
    1) The variable isn't final, so something could be setting it to null subsequent to initialization.
    I just checked, and it's initialized once. Though I think we will change that code so it's declared as final for better code hygiene, since that is our intent.
    >
    2) Since it's a static initializer, it will be null while earlier (depended-on) static initializers are running. One place I've seen this (involving logging code, actually): Class A logs inside a static initializer, and logging is configured to use a formatter which involves class B, and class B has a static dependency on class A.
    Yes, that's a good suggestion. In this case, we're instantiating a java.util.concurrent.ConcurrentHashMap, which would seem free of that sort of issue. Unless there's something different with the Glassfish environment?
  • 5. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    804877 Newbie
    Currently Being Moderated
    Jeffstyr wrote:
    So that's all to say, look and see if you have any logging inside static initializers, and also check whether you have any fancy log formatters configured. Also this is the sort of problem that can come or go if you happen to touch classes in a different order, as the result of a seemingly unrelated code change.
    I'm fairly certain that we're not doing any of that, although I'll definitely go check.

    Also, I just ran it up in the beta of GF 4.0 that I had laying around and I get the following message at startup:

    SEVERE: May 24, 2013 3:07:09 PM com.sleepycat.je.utilint.LoggerUtils logMsg
    INFO: No file selected for cleaning. totalUtilization: 93 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

    So far, GF 4.0 is working with re-deploys, so perhaps it's something in GF 3.1.2.2?

    I'll keep poking at it.
  • 6. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    909806 Newbie
    Currently Being Moderated
    Linda Lee wrote:
    1) The variable isn't final, so something could be setting it to null subsequent to initialization.
    I just checked, and it's initialized once. Though I think we will change that code so it's declared as final for better code hygiene, since that is our intent.
    You might also just want to use ThreadLocals rather than thread-keyed ConcurrentHashMaps (which could potentially leak entries if a thread exits with an entry in place), since this is the sort of thing they are made for. I don't think it's the problem though.
    2) Since it's a static initializer, it will be null while earlier (depended-on) static initializers are running. One place I've seen this (involving logging code, actually): Class A logs inside a static initializer, and logging is configured to use a formatter which involves class B, and class B has a static dependency on class A.
    Yes, that's a good suggestion. In this case, we're instantiating a java.util.concurrent.ConcurrentHashMap, which would seem free of that sort of issue.
    I was more worried about some static initializer above this in the file (which would run before the ConcurrentHashMap is created), but I don't see anything like that in the je-5.0.73 source, and I think it would have to be showing up in the stacktrace to be a problem. (I don't have the 5.0.58 source to be sure it's the same, since it's no longer posted).

    But (again, based on the 5.0.73 source), it looks like LoggerUtils.logMsg() must have have just successfully accessed LoggerUtils.envMap just before calling through to ConsoleRedirectHandler.publish() which then NPEs on it, so the only explanation that make sense is that there are two different class loaders involved, leading to two different instances of the LoggerUtils class itself coming into play. I don't know anything about Glassfish, but this is the sort of thing that a redeploy-without-restarting technology does, so I bet the problem is related to using Glassfish.
  • 7. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    804877 Newbie
    Currently Being Moderated
    Jeffstyr wrote:
    I was more worried about some static initializer above this in the file (which would run before the ConcurrentHashMap is created), but I don't see anything like that in the je-5.0.73 source, and I think it would have to be showing up in the stacktrace to be a problem. (I don't have the 5.0.58 source to be sure it's the same, since it's no longer posted).

    But (again, based on the 5.0.73 source), it looks like LoggerUtils.logMsg() must have have just successfully accessed LoggerUtils.envMap just before calling through to ConsoleRedirectHandler.publish() which then NPEs on it, so the only explanation that make sense is that there are two different class loaders involved, leading to two different instances of the LoggerUtils class itself coming into play. I don't know anything about Glassfish, but this is the sort of thing that a redeploy-without-restarting technology does, so I bet the problem is related to using Glassfish.
    I'm thinking that this must be the problem too. For what it's worth, it seems to be at least a little bit timing dependent: some times I can get in a couple of re-deploys before things go wonky.

    I determined this evening that this problem also appears under glassfish 3.1.2.2 on Windows (7, 64 bit, if that makes any difference.)

    Any suggestions about how I could track this down? I'd be happy to try a newer version of JE, but I think I'll see the same thing.

    If you (Linda) would like me to try a ThreadLocal but no ConcurrentHashMap version, I'd be happy to try that too.
  • 8. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    804877 Newbie
    Currently Being Moderated
    This is happening with the latest version of JE too.
  • 9. Re: NPE in ConsoleRedirectHandler when reopening a entity store during redeploy
    Linda Lee Journeyer
    Currently Being Moderated
    Steve,

    Earlier, in the conversation with Jeff Styr, we agreed that com.sleepycat.je.utilint.LoggerUtils.envMap should be made final, for greater code clarity. My colleague Tim pointed out that this might actually have a beneficial effect on this strange initialization problem, because it would enforce a certain ordering of initialization. If you think that is worth trying, I can send you a je.jar, or you could apply the following diff:
    --- a/src/com/sleepycat/je/utilint/LoggerUtils.java
    +++ b/src/com/sleepycat/je/utilint/LoggerUtils.java
    @@ -118,25 +118,25 @@ import com.sleepycat.je.log.Trace;
      * String) instead of Logger.log(Level, String)
      */
     public class LoggerUtils {
    
         /*
          * Environment state to be used by a logger. Must be set and released
          * per logger call.
          */
    -    static Map<Thread, EnvironmentImpl> envMap =
    +    static final Map<Thread, EnvironmentImpl> envMap =
             new ConcurrentHashMap<Thread, EnvironmentImpl>();
    
         /*
          * Formatter state to be used by a logger. Must be set and released
          * per logger call. Used by logging calls that do not have an available
          * environment.
          */
    -    static Map<Thread, Formatter> formatterMap =
    +    static final Map<Thread, Formatter> formatterMap =
             new ConcurrentHashMap<Thread, Formatter>();
    
         public static final String NO_ENV = ".noEnv";
         public static final String FIXED_PREFIX = ".fixedPrefix";
         private static final String PUSH_LEVEL = ".push.level";
    
         /**
          * Get a logger which is configured to use the shared console, memory, and

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points