2

I am using JUL in my application. Normally, Netbeans opens an output tab that reads "Tomcat" and shows the logs I produce. It was working fine. But suddenly, I realise that my logs are not shown at all, only the System.out get printed. Not even the higuest LOG.log(Level.SEVERE, ".....

} catch(Exception e) {
      System.out.println("This gets printed in Netbeans tab");
      LOG.log(Level.SEVERE, "This doesnt");
}

I suspect it can be a library I included, which is messing with my logs. Is that possible at all? Can a librray change the way my logs are shown? How can I investigate this, since I am a bit lost?

user1156544
  • 1,725
  • 2
  • 25
  • 51

1 Answers1

2

I suspect it can be a library I included, which is messing with my logs. Is that possible at all?

Yes. The JUL to SLF4J Bridge can remove the console handler from the JUL root logger. Some libraries invoke LogManager.reset which can remove and close all handlers.

Can a library change the way my logs are shown?

Yes. Once the a log bridge is installed the JUL records are no longer formatted by the JUL formatters.

How can I investigate this, since I am a bit lost?

Modifying the logger tree requires permissions so you can install a SecurityManager with all permissions but then turn on debug tracing with -Djava.security.debug="access,stack" to determine the caller that is modifying the logger tree.

If that doesn't work you can use good ole' System.out to print the logger tree and the attached handlers before and after a library is loaded. Then start adding an removing libraries until you see the logger change.

import java.io.File;
import java.io.IOException;
import java.io.PrintStream;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.Enumeration;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;

public class DebugLogging {

    private static final Logger log = Logger.getLogger("test");

    public static void main(String[] a) {
        log.log(Level.FINEST, "Finest");
        log.log(Level.FINER, "FINER");
        log.log(Level.FINE, "FINE");
        log.log(Level.CONFIG, "CONFIG");
        log.log(Level.INFO, "INFO");
        log.log(Level.WARNING, "WARNING");
        log.log(Level.SEVERE, "SEVERE");
        log.finest("Finest Log");
        log.finer("Finer Log");
        log.fine("Fine Log");
        log.config("Config Log");
        log.info("Info Log");
        log.warning("Warning Log");
        log.severe("Severe Log");
        printConfig(System.err);
    }

    private static void printConfig(PrintStream ps) {
        String cname = System.getProperty("java.util.logging.config.class");
        if (cname != null) {
            try {
                ClassLoader sys = ClassLoader.getSystemClassLoader();
                Class<?> c = Class.forName(cname, false, sys);
                ps.println(sys.getClass().getName() +" found log configuration class " + c.getName());
            } catch (LinkageError | ClassNotFoundException | RuntimeException cnfe) {
                ps.println("Unable to load " + cname);
                cnfe.printStackTrace(ps);
            }
        } else {
            ps.println("java.util.logging.config.class was null");
        }
        
        String file = System.getProperty("java.util.logging.config.file");
        if (file != null) {
           ps.println("java.util.logging.config.file=" + file);
           try {
               ps.println("CanonicalPath=" + new File(file).getCanonicalPath());
           } catch (RuntimeException | IOException ioe) {
               ps.println("Unable to resolve path for " + file);
               ioe.printStackTrace(ps);
           }

           try {
               Path p = Paths.get(file);
               if (Files.isReadable(p)) {
                   ps.println(file + " is readable and has size " + Files.size(p));
               } else {
                   if (Files.exists(p)) {
                       ps.println(file + " exists for " + System.getProperty("user.name") + " but is not readable.");
                   } else {
                       ps.println(file + " doesn't exist for " + System.getProperty("user.name"));
                   }
               }
           } catch (RuntimeException | IOException ioe) {
               ps.println("Unable to read " + file);
               ioe.printStackTrace(ps);
           }
        } else {
            ps.println("java.util.logging.config.file was null");
        }

        LogManager lm = LogManager.getLogManager();
        ps.append("LogManager=").println(lm.getClass().getName());
        synchronized (lm) {
            Enumeration<String> e = lm.getLoggerNames();
            while (e.hasMoreElements()) {
                Logger l = lm.getLogger(e.nextElement());
                if (l != null) {
                    print(l, ps);
                }
            }
        }
    }

    private static void print(Logger l, PrintStream ps) {
        String scn = l.getClass().getSimpleName();
        ps.append("scn=").append(scn).append(", n=").append(l.getName())
                .append(", uph=").append(String.valueOf(l.getUseParentHandlers()))
                .append(", l=").append(String.valueOf(l.getLevel()))
                .append(", fl=").println(l.getFilter());
        for (Handler h : l.getHandlers()) {
            ps.append("\t").append(l.getName()).append("->")
                    .append(h.getClass().getName()).append(", h=")
                    .append(String.valueOf(h.getLevel())).append(", fl=")
                    .append(String.valueOf(h.getFilter())).println();
        }
    }
}
jmehrens
  • 10,580
  • 1
  • 38
  • 47
  • I have been trying to run this code but I am not sure where. So I am using Maven which loads my dependencies... The potential offenders are - Apache Shiro, and extension of shiro and a database dependency. But I am not sure where to put that in my app to be executed before they are loaded – user1156544 Jul 06 '17 at 08:06
  • @user1156544 Start out with just making that code execute and capturing the results. If there are no handlers or the levels are not set right that gives you a starting point. – jmehrens Jul 06 '17 at 13:37
  • Yes I did that. I executed the code in one of my classes and the result was a lot of printed lines like these.... – user1156544 Jul 06 '17 at 16:20
  • scn=RootLogger, n=, l=FINE, fl=null RootLogger->org.apache.juli.AsyncFileHandler, h=FINE, fl=nullscn=Logger, n=com.sun.xml.internal.bind.v2.schemagen.XmlSchemaGenerator, l=null, fl=null scn=Logger, n=org.apache.shiro.web.faces.tags.PrincipalTag, l=null, fl=null scn=Logger, n=org.apache.bval.jsr, l=null, fl=null scn=Logger, n=org.apache.webbeans.conversation.ConversationManager, l=null, fl=null scn=Logger, n=org.apache.shiro.web.faces, l=null, fl=null scn=Logger, n=org.apache.http.impl.execchain.ProtocolExec, l=null, fl=null scn=Logger, n=com.google.inject, l=null, fl=null – user1156544 Jul 06 '17 at 16:20
  • Between all these lines there were a couple refering my application. What should I look inside this print and how can I fix it? – user1156544 Jul 06 '17 at 16:22
  • 1
    @user1156544 That output shows that there is no console handler installed on the root logger. This is why you don't see console output. Either it was never added or something removed it. – jmehrens Jul 06 '17 at 17:20
  • I see, that makes sense. Do you know from where I could add it back after dependencies are loaded? I am a bit lost because there is no "entry point" in a web app or I dont know where it is. Or if there is a way for me to set my logging file in a way that no later dependency can remove my handler – user1156544 Jul 07 '17 at 09:47
  • 1
    [Yes.](https://stackoverflow.com/questions/35071921/is-it-possible-to-make-a-handler-recognize-that-it-had-been-removed/35072783#35072783) Your best bet is to use the `SecurityManager` step from my answer and try to figure out the caller that is removing the handler. You could also try calling `LogManager.readConfiguration()` to undo programmatic configuration changes. – jmehrens Jul 07 '17 at 13:22