dev@glassfish.java.net

GlassFish log messages contain inconsistent thread ids

From: Sahoo <sanjeeb.sahoo_at_oracle.com>
Date: Sat, 12 Mar 2011 09:34:15 +0530

While trying to analyse the root cause of a deadlock, I had to analyse
the log records and I found log messages containing different thread ids
even though the messages were all logged by the same thread. This is
quite unacceptable behavior of the logging module. The root cause seems
to be the following code in LogDomains.java which modifies the threadId
set by jdk logging code:

             cLogger = new Logger(loggerName, null) {

                 /* override this method to set the the thread id so all
handlers get the same info*/
                 public void log(LogRecord record) {
                     ...
* record.setThreadID((int)
Thread.currentThread().getId());
* super.log(record);
                     ...
                 }

The above method created sets the thread id based on actual thread's id,
where as JDK's LogRecord class uses a different identifier as thread id
as the source code of java.util.logging.Logger shows:

public class LogRecord implements java.io.Serializable {
     private static int nextThreadId=10;

     private static ThreadLocal threadIds = new ThreadLocal();

     public LogRecord(Level level, String msg) {
     ...
     // Assign a thread ID and a unique sequence number.
     synchronized (LogRecord.class) {
         sequenceNumber = globalSequenceNumber++;
         Integer id = (Integer)threadIds.get();
* if (id == null) {
         id = new Integer(nextThreadId++);
         threadIds.set(id);
         }
* threadID = id.intValue();
     }
     millis = System.currentTimeMillis();
     needToInferCaller = true;
    }
}

Since the code in LogDomains' is not applicable for loggers not known to
LogDomains, any third party's module's log messages will always be
logged with a different thread id than glassfish originated log
messages. I suggest we remove this special code from LogDomains to avoid
unnecessary confusion. WDOT?

Sahoo

ps: Marina, Mitesh, I hope this explains why I was seeing different
thread id for all EclipseLink messages.