glassfish
  1. glassfish
  2. GLASSFISH-15350

Thread Id is coming different in server.log file

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 3.1_ms07
    • Fix Version/s: 3.1_ms08
    • Component/s: logging
    • Labels:
      None
    • Environment:

      All Platform

      Description

      If user starts domain using following command

      ./asadmin start-domain --debug --verbose
      It starts domain properly with all required thread ids in logging message.

      On console user can see following message with Thread Id 60.
      [#|2010-12-27T11:20:28.114+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=60;_ThreadName=Thread-25;|Binding RMI port to *:8686|#]

      [#|2010-12-27T11:20:28.705+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=60;_ThreadName=Thread-25;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#]

      But when you open and see server.log file same messages is logged with different thread Id 17.
      [#|2010-12-27T11:20:28.114+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=17;_ThreadName=Thread-1;|Binding RMI port to *:8686|#]

      [#|2010-12-27T11:20:28.705+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=17;_ThreadName=Thread-1;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#]

        Activity

        Hide
        naman_mehta added a comment -

        How bad is its impact? (Severity)
        Major. You can find wrong thread Ids in log messages in server.log file.

        How often does it happen? Will many users see this problem? (Frequency)
        Regularly. Yes.

        How much effort is required to fix it? (Cost)
        Need to remove current thread id from logging message during formating the log message. As it's not needed.

        What is the risk of fixing it and how will the risk be mitigated? (Risk)
        No risk. Just removing thread Id from log message. Attached the file diff for the same.

        File diff:
        Index: src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java
        ===================================================================
        — src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java (revision 44094)
        +++ src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java (working copy)
        @@ -246,9 +246,7 @@
        recordBuffer.append(record.getLoggerName()).append(FIELD_SEPARATOR);

        recordBuffer.append("_ThreadID").append(NV_SEPARATOR);

        • record.setThreadID((int) Thread.currentThread().getId());
          + //record.setThreadID((int) Thread.currentThread().getId());
          recordBuffer.append(record.getThreadID()).append(NVPAIR_SEPARATOR);

        recordBuffer.append("_ThreadName").append(NV_SEPARATOR);

        Should I make this changes.

        After fixing above issue. You can find following messages on console and server.log. Both having same Message Ids.

        On Console:
        [#|2010-12-27T11:27:41.937+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-28;|Binding RMI port to *:8686|#]

        [#|2010-12-27T11:27:42.326+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-28;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#]

        In server.log:
        [#|2010-12-27T11:27:41.937+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-1;|Binding RMI port to *:8686|#]

        [#|2010-12-27T11:27:42.326+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-1;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#]

        Show
        naman_mehta added a comment - How bad is its impact? (Severity) Major. You can find wrong thread Ids in log messages in server.log file. How often does it happen? Will many users see this problem? (Frequency) Regularly. Yes. How much effort is required to fix it? (Cost) Need to remove current thread id from logging message during formating the log message. As it's not needed. What is the risk of fixing it and how will the risk be mitigated? (Risk) No risk. Just removing thread Id from log message. Attached the file diff for the same. File diff: Index: src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java =================================================================== — src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java (revision 44094) +++ src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java (working copy) @@ -246,9 +246,7 @@ recordBuffer.append(record.getLoggerName()).append(FIELD_SEPARATOR); recordBuffer.append("_ThreadID").append(NV_SEPARATOR); record.setThreadID((int) Thread.currentThread().getId()); + //record.setThreadID((int) Thread.currentThread().getId()); recordBuffer.append(record.getThreadID()).append(NVPAIR_SEPARATOR); recordBuffer.append("_ThreadName").append(NV_SEPARATOR); Should I make this changes. After fixing above issue. You can find following messages on console and server.log. Both having same Message Ids. On Console: [#|2010-12-27T11:27:41.937+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-28;|Binding RMI port to *:8686|#] [#|2010-12-27T11:27:42.326+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-28;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#] In server.log: [#|2010-12-27T11:27:41.937+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-1;|Binding RMI port to *:8686|#] [#|2010-12-27T11:27:42.326+0530|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=65;_ThreadName=Thread-1;|JMXStartupService: Started JMXConnector, JMXService URL = service:jmx:rmi://naman:8686/jndi/rmi://naman:8686/jmxrmi|#]
        Hide
        Nazrul added a comment -

        Requested Carla and Jerome to review this change

        Show
        Nazrul added a comment - Requested Carla and Jerome to review this change
        Hide
        Nazrul added a comment -

        Would the above change re-introduce the following issue: http://java.net/jira/browse/GLASSFISH-11813

        Show
        Nazrul added a comment - Would the above change re-introduce the following issue: http://java.net/jira/browse/GLASSFISH-11813
        Hide
        Nazrul added a comment -

        According to Naman, issue GLASSFISH-11813 is not re-introduced with the above fix. Approved for checkin.

        Show
        Nazrul added a comment - According to Naman, issue GLASSFISH-11813 is not re-introduced with the above fix. Approved for checkin.
        Hide
        naman_mehta added a comment -

        Made check ins for the same.

        Committed revision 44133.

        Show
        naman_mehta added a comment - Made check ins for the same. Committed revision 44133.
        Hide
        Sanjeeb Sahoo added a comment -

        I am amazed by the lack of attention to details. This bug is still not fixed. Whilist the threadId is printed correctly, the thread name is still incorrect.

        Show
        Sanjeeb Sahoo added a comment - I am amazed by the lack of attention to details. This bug is still not fixed. Whilist the threadId is printed correctly, the thread name is still incorrect.
        Hide
        naman_mehta added a comment -

        The issue is due to LogRecord is storing thread ID and which is used during formatting the log message but the thread Name is not available at the same time. Need to assign thread name based on thread id.

        Show
        naman_mehta added a comment - The issue is due to LogRecord is storing thread ID and which is used during formatting the log message but the thread Name is not available at the same time. Need to assign thread name based on thread id.
        Hide
        Sanjeeb Sahoo added a comment -

        Thread name can't be obtained from threadId. So, if we really want thread name to be reported, then it must be put into log record in the same thread that tries to log message.

        Show
        Sanjeeb Sahoo added a comment - Thread name can't be obtained from threadId. So, if we really want thread name to be reported, then it must be put into log record in the same thread that tries to log message.
        Hide
        sandeep.shrivastava added a comment -

        The java.util.logging.LogRecord object does not allow for capturing additional request metadata that is later available in another thread at the time of writing the record to the log file. A possible fix for this issue could be to write to the log file in the original thread that initiated the logging request. The log file rotation can still be done asynchronously.

        Thoughts? Comments?

        Show
        sandeep.shrivastava added a comment - The java.util.logging.LogRecord object does not allow for capturing additional request metadata that is later available in another thread at the time of writing the record to the log file. A possible fix for this issue could be to write to the log file in the original thread that initiated the logging request. The log file rotation can still be done asynchronously. Thoughts? Comments?
        Hide
        rajendra_inamdar added a comment -

        One way to handle this could be to create a custom LogRecord where additional contextual information can be stored. It can be put on the queue. This info can be used during formatting when the custom LogRecord is processed in the consumer thread.

        Show
        rajendra_inamdar added a comment - One way to handle this could be to create a custom LogRecord where additional contextual information can be stored. It can be put on the queue. This info can be used during formatting when the custom LogRecord is processed in the consumer thread.
        Hide
        rajendra_inamdar added a comment -

        Fix submitted:

        r55516 | rajendra.inamdar@oracle.com | 2012-08-16 13:34:31 -0700 (Thu, 16 Aug 2012) | 2 lines
        Changed paths:
        M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/GFFileHandler.java
        A /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/GFLogRecord.java
        M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/ODLLogFormatter.java
        M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java

        Fix incorrect thread-name in the server log records.

        Show
        rajendra_inamdar added a comment - Fix submitted: r55516 | rajendra.inamdar@oracle.com | 2012-08-16 13:34:31 -0700 (Thu, 16 Aug 2012) | 2 lines Changed paths: M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/GFFileHandler.java A /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/GFLogRecord.java M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/ODLLogFormatter.java M /trunk/main/nucleus/core/logging/src/main/java/com/sun/enterprise/server/logging/UniformLogFormatter.java Fix incorrect thread-name in the server log records.
        Hide
        Bobby Bissett added a comment -

        What is the status of this issue now that a patch was submitted? The incorrect thread names in the log file caused us a great deal of confusion on our project. If it helps, am attaching a test servet that shows the problem. Here is the output I see:

        Using GF 2.1.1-b31:

        Terminal output:
        [#|2012-10-05T09:58:12.998-0400|INFO|sun-appserver2.1|testLogger|_ThreadID=18;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#]
        Log:
        [#|2012-10-05T09:58:12.998-0400|INFO|sun-appserver2.1|testLogger|_ThreadID=18;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#]

        Using GF 3.1.2.2:

        Terminal output:
        [#|2012-10-05T10:02:06.340-0400|INFO|glassfish3.1.2|testLogger|_ThreadID=20;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#]
        Log:
        [#|2012-10-05T10:02:06.340-0400|INFO|glassfish3.1.2|testLogger|_ThreadID=20;_ThreadName=Thread-3;|Hi, I am bobby_test_thread|#]

        Clearly, the log file record for GF 3.X should match the others.

        Show
        Bobby Bissett added a comment - What is the status of this issue now that a patch was submitted? The incorrect thread names in the log file caused us a great deal of confusion on our project. If it helps, am attaching a test servet that shows the problem. Here is the output I see: Using GF 2.1.1-b31: Terminal output: [#|2012-10-05T09:58:12.998-0400|INFO|sun-appserver2.1|testLogger|_ThreadID=18;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#] Log: [#|2012-10-05T09:58:12.998-0400|INFO|sun-appserver2.1|testLogger|_ThreadID=18;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#] Using GF 3.1.2.2: Terminal output: [#|2012-10-05T10:02:06.340-0400|INFO|glassfish3.1.2|testLogger|_ThreadID=20;_ThreadName=bobby_test_thread;|Hi, I am bobby_test_thread|#] Log: [#|2012-10-05T10:02:06.340-0400|INFO|glassfish3.1.2|testLogger|_ThreadID=20;_ThreadName=Thread-3;|Hi, I am bobby_test_thread|#] Clearly, the log file record for GF 3.X should match the others.
        Hide
        rajendra_inamdar added a comment -

        This issue is fixed in 4.0. As per SE advice, marking this one fixed and opened a bugdb issue.

        On 10/26/12 5:03 AM, manoj malhotra wrote:
        >
        > Hi All-
        >
        > SE works via bugdb only.
        > Open a bug in bugdb and let me know, I can target it for 3.1.2-patch#4.
        > Same (dev) engineer who has fixed bug for 4.0 need to backport it for SE tails.
        >
        > Kind Regards,
        > Manoj

        Show
        rajendra_inamdar added a comment - This issue is fixed in 4.0. As per SE advice, marking this one fixed and opened a bugdb issue. On 10/26/12 5:03 AM, manoj malhotra wrote: > > Hi All- > > SE works via bugdb only. > Open a bug in bugdb and let me know, I can target it for 3.1.2-patch#4. > Same (dev) engineer who has fixed bug for 4.0 need to backport it for SE tails. > > Kind Regards, > Manoj
        Hide
        Bobby Bissett added a comment -

        Is there any way I can get a patch (or pointer to the commit and I'll find the files) so I can rebuild my 3.1.2.2 with this change?

        Show
        Bobby Bissett added a comment - Is there any way I can get a patch (or pointer to the commit and I'll find the files) so I can rebuild my 3.1.2.2 with this change?

          People

          • Assignee:
            sandeep.shrivastava
            Reporter:
            naman_mehta
          • Votes:
            1 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Due:
              Created:
              Updated:
              Resolved:

              Time Tracking

              Estimated:
              Original Estimate - 2 hours
              2h
              Remaining:
              Remaining Estimate - 2 hours
              2h
              Logged:
              Time Spent - Not Specified
              Not Specified