Issue Details (XML | Word | Printable)

Key: GLASSFISH-15350
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Critical Critical
Assignee: sandeep.shrivastava
Reporter: naman_mehta
Votes: 1
Watchers: 6
Operations

If you were logged in you would be able to see more operations.
glassfish

Thread Id is coming different in server.log file

Created: 26/Dec/10 09:52 PM   Updated: 26/Oct/12 02:56 PM  Due: 29/Dec/10   Resolved: 26/Oct/12 02:39 PM
Component/s: logging
Affects Version/s: 3.1_ms07
Fix Version/s: 3.1_ms08

Time Tracking:
Original Estimate: 2 hours
Original Estimate - 2 hours
Remaining Estimate: 2 hours
Remaining Estimate - 2 hours
Time Spent: Not Specified
Time Spent - Not Specified

File Attachments: 1. Java Source File TestServlet.java (0.8 kB) 05/Oct/12 02:13 PM - Bobby Bissett

Environment:

All Platform


Tags: 3_1-approved
Participants: Bobby Bissett, naman_mehta, Nazrul, rajendra_inamdar, sandeep.shrivastava and Sanjeeb Sahoo


 Description  « Hide

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|#]



naman_mehta added a comment - 26/Dec/10 09:58 PM

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|#]


Nazrul added a comment - 27/Dec/10 02:22 PM

Requested Carla and Jerome to review this change


Nazrul added a comment - 27/Dec/10 03:23 PM

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


Nazrul added a comment - 28/Dec/10 10:44 AM

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


naman_mehta added a comment - 28/Dec/10 09:19 PM

Made check ins for the same.

Committed revision 44133.


Sanjeeb Sahoo added a comment - 09/Jul/12 03:24 AM

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.


naman_mehta added a comment - 09/Jul/12 09:25 AM

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.


Sanjeeb Sahoo added a comment - 09/Jul/12 10:45 AM

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.


sandeep.shrivastava added a comment - 26/Jul/12 05:44 PM

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?


rajendra_inamdar added a comment - 27/Jul/12 08:01 PM

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.


rajendra_inamdar added a comment - 24/Aug/12 08:14 PM

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.


Bobby Bissett added a comment - 05/Oct/12 02:13 PM

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.


rajendra_inamdar added a comment - 26/Oct/12 02:39 PM

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


Bobby Bissett added a comment - 26/Oct/12 02:56 PM

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?