Bug 44888 - problem in showing Filename and Line number in log file
problem in showing Filename and Line number in log file
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.2beta
PC Windows XP
: P2 normal
: ---
Assigned To: log4j-dev
:
: 45364 47014 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2008-04-28 03:10 UTC by Chanchal
Modified: 2009-10-10 12:41 UTC (History)
3 users (show)



Attachments
Log file with defects (995.30 KB, application/octet-stream)
2008-04-28 03:10 UTC, Chanchal
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Chanchal 2008-04-28 03:10:04 UTC
Created attachment 21868 [details]
Log file with defects

Hi.
I am using Log4j ver 1.2.8
here sometime I get question mark instead of file name and line number 
see below for details



[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,415] [INFO] - The customer with customer number 00797343 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,424] [INFO] - The customer with customer number 00119972 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,431] [INFO] - The customer with customer number 00575408 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,437] [INFO] - The customer with customer number 00156617 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,494] [INFO] - The customer with customer number 00850370 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,510] [INFO] - The customer with customer number 00124816 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,522] [INFO] - The customer with customer number 00202916 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,575] [INFO] - The customer with customer number 00613744 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [AbstractDataLoad.java : 1098 ] [19 Mar 2008 06:20:52,582] [INFO] - The customer with customer number 00472839 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,783] [INFO] - The customer with customer number 00474659 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,790] [INFO] - The customer with customer number 00338894 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,798] [INFO] - The customer with customer number 00887960 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,824] [INFO] - The customer with customer number 00884282 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,830] [INFO] - The customer with customer number 00652635 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,836] [INFO] - The customer with customer number 00926011 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,850] [INFO] - The customer with customer number 00677557 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,857] [INFO] - The customer with customer number 00700285 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,871] [INFO] - The customer with customer number 00798306 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,882] [INFO] - The customer with customer number 00394582 and LegacyCmrCtryCode 649 was missing in customer table CTMTCUSCA and has been inserted into the customer table CTMTCUSCA
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,898] [INFO] - The customer with customer number 00809820 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,907] [INFO] - The customer with customer number 00001129 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,917] [INFO] - The customer with customer number 00577303 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,927] [INFO] - The customer with customer number 00067160 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,937] [INFO] - The customer with customer number 00127121 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,948] [INFO] - The customer with customer number 00394710 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,956] [INFO] - The customer with customer number 00070602 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,965] [INFO] - The customer with customer number 00126677 and LegacyCmrCtryCode 706 was missing in customer table CTMTCUSFR and has been inserted into the customer table CTMTCUSFR
[catSwgDataLoad] [? : ? ] [19 Mar 2008 06:20:52,977] [INFO

More you can find in Attached file

here all the logs are from same java file and same line number but as you can see here after sometime logging file name and line number the loger has some problem it can not log file name and line number 

below is the setting for log4j in application 

# Appender swg_err uses the PatternLayout.
log4j.logger.swg_err = ,swg_err
log4j.appender.swg_err.layout=org.apache.log4j.PatternLayout
log4j.appender.swg_err.layout.ConversionPattern=[catSwgDataLoad] [%F : %L ] %d{[dd MMM yyyy HH:mm:ss,SSS]} [%p] - %m%n  


Please give me solution ASAP
Comment 1 Curt Arnold 2008-04-28 08:54:24 UTC
The most common reason for class and line number extraction to fail is that the class file was compiled without debug information.  However, nothing suggests that you recompiled in the middle of collecting the log.

Unless somebody has run into this before, it seems unlikely that we'd be able to diagnose the problem without more information.

The following information would be very helpful:

Does the problem occur with log4j 1.2.15?  It is possible that you are encountering a bug that has already been fixed in the several years since log4j 1.2.8.

What JVM are you using (java -v)?  LocationInfo depends on parsing the output of Throwable.printStackTrace() to determine the calling class and line number and as such may be affected by differences in JVM's.  JDK 1.4 added more reliable methods to access this information, but log4j still targets earlier JDK's.

If you run your app under a debugger, you could place break points in the returns within LocationInformation constructor.  When the extraction is working properly, the constructor should exit after the last line.  Knowing which early exit is used and the contents of the "s" variable would be key to identifying the problem.

Can you provide a sample program that reproduces the defect?


Comment 2 Ralph Goers 2008-05-15 00:35:44 UTC
I just tried this with log4j 1.2.15 and could not get my location information. I am calling the log method from a class that uses SLF4J and does

        if (logger.isTraceEnabled() && logger instanceof LocationAwareLogger)
        {
            ((LocationAwareLogger)logger).log(FLOW_MARKER, FQCN, LocationAwareLogger.TRACE_INT, "entry", null);
        }

where FQCN is the fully qualified name of my class. This works correctly with logback. I traced this down and was able to determine that the information being captured in LocationInfo is wrong.  I was able to hack together a bypass by creating an appender using the same package name as LocationInfo and doing

    protected void append(LoggingEvent event)
    {
        LocationInfo info = event.getLocationInformation();
        String fqcn = event.getFQNOfLoggerClass();
        Throwable throwable = new Throwable();
        StackTraceElement[] steArray = throwable.getStackTrace();

        int found = LINE_NA;
        for (int i=0; i < steArray.length; ++i)
        {
            if (steArray[i].getClassName().equals(fqcn))
            {
                found = i + 1;
            }
            else if (found != LINE_NA)
            {
                break;
            }
        }
        if (found == LINE_NA)
        {
            return;
        }
        info.className = steArray[found].getClassName();
        info.fileName = steArray[found].getFileName();
        info.lineNumber = Integer.toString(steArray[found].getLineNumber());
        info.methodName = steArray[found].getMethodName();
        info.fullInfo = steArray[found].toString();
    }

By putting this appender first the correct LocationInfo is returned. BTW - this code came straight from Logback.
Comment 3 Ralph Goers 2008-05-15 00:42:00 UTC
java version "1.5.0_14"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_14-b03)
Java HotSpot(TM) Client VM (build 1.5.0_14-b03, mixed mode, sharing)

My guess is this is the real problem. 
Comment 4 Curt Arnold 2008-05-15 13:39:43 UTC
Ralph, it sounds like you have an environment and sample app that reveals a defect in the LocationInfo class.  It would be very helpful if you could provide some insight into the defect so that could be understood.  Having a work-around is good, but it would be better to understand the defect and try to resolve it appropriately.

Could you provide any of the following info (the more, the better):

What platform are you running on (Windows, Mac, Linux, etc)?

Do the unit tests pass in your environment?

If the current tests pass, could you write a unit test that test the defective code and fails?

If you can't write a unit test, could you write a sample app that demonstrates the problem?

Can you step through the LocationInformation constructor and identify where and why the location extraction code breaks down?  Previously this has been due to a slightly different format of the output from printStackTrace, for example, JRocket used spaces instead of tabs if I remember correctly.

Throwable.getStackTrace() was added in JDK 1.4, so depending on it would not be consistent with log4j's targeting of JDK 1.3 or later.  However, it might be tolerable to sniff for it using reflection or catch a MethodNotFound exception and then fallback to the older code.

logback is licensed under the LGPL, so use of logback code without explicit licensing from the original author is inconsistent with the ASF license and can't go into log4j.  If the underlying problem is adequately identified, I'm sure that we can come up with an appropriate solution without referring to the logback code.

Comment 5 Ralph Goers 2008-05-15 17:24:20 UTC
 My environment: Ubuntu running in VMWare on Windows NT.
Linux testuser-desktop 2.6.22-14-generic #1 SMP Tue Feb 12 07:42:25 UTC 2008 i686 GNU/Linux

I haven't tried building log4j itself, but I certainly can and I'd be happy to see if I can come up with something that fails if the current unit tests don't. 

As for stepping through the current code that seems like a waste of time. I'd prefer to write something that leverages Thread.currentThread().getStackTrace() and just use that if the JVM is 1.5 or better. I'd be happy to come up with a way to do that. That way it should also fix the performance problems the current code has as well as be a lot less susceptible to parsing problems. If I can't see any good way to do that then I will resort to fixing the current code.

As for the LGPL vs Apache license issues, I'm well aware of them as I've participated on legal-discuss and been an Apache committer for years. 
Comment 6 Ralph Goers 2008-05-16 00:49:47 UTC
I ran the build and it was successful. I modified the Appender code I showed below to print the stacktrace and the info in LocationInfo before it was corrected. From that I was able to determine what the problem is. The code is only matching up to a class name the length of the FQCN. In the case below that means it matches LoggerUtilTest when it shouldn't have. I modified LocationInfoTest with a new test case and created a new class to simulate the behvior and it failed. If included both after the stack trace.

I'll still look into creating a Java 5 version of this. However you fix this for 1.3 is just going to make it even slower.

className: sun.reflect.NativeMethodAccessorImpl
filename: ?
lineNumber: ?
methodName: invoke0
FQCN: com.diginsite.services.logging.LoggerUtil
java.lang.Throwable
        at org.apache.log4j.spi.LocationAppender.append(LocationAppender.java:20)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:509)
        at com.diginsite.services.logging.LoggerUtil.entering(LoggerUtil.java:121)
        at com.diginsite.services.logging.LoggerUtilTest.testDefaultEntering(LoggerUtilTest.java:46)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)


new test case for LocationInfoTest.java

    /**
     * Tests creation of location info from a throwable and where the
     * FQCN is part of the caller's name.
     */
    public void testLocationInfo() {
        LocationInfo li = new LocationIn().getLocationInfo();
        final String className = LocationInfoTest.class.getName();
        final String methodName = "testLocationInfo";
        final String fileName = "LocationInfoTest.java";
        final String lineNumber = "49";
        assertEquals(className, li.getClassName());
        assertEquals(methodName, li.getMethodName());
        assertEquals(fileName, li.getFileName());
        assertEquals(lineNumber, li.getLineNumber());
        assertEquals(className + "."  + methodName
                + "(" + fileName + ":" + lineNumber + ")",
                li.fullInfo);
    }

LocationIn.java 

package org.apache.log4j.spi;

/**
 *
 */
public class LocationIn
{
    public LocationInfo getLocationInfo()
    {
       Throwable t = new Throwable();
       String fqcn = LocationIn.class.getName();
       return new LocationInfo(t, fqcn);
    }
}
        
Comment 7 Curt Arnold 2008-05-19 10:32:00 UTC
Rev 657869 should fix issue reported by Ralph Goers.  Likely not same issue that Chanchal encountered, but since he did not provide any additional information can be sure.  Chanchal, if this fix does not address your problem, please file a new bug report and provide the information that was requested.

Using Throwable.getStackElement() when JDK 1.4+ or later is available seems like a desirable improvement, but that should be done as a different bug report.  I've filed bug 45039 for that enhancement.
Comment 8 Curt Arnold 2008-07-11 22:46:06 UTC
*** Bug 45364 has been marked as a duplicate of this bug. ***
Comment 9 Curt Arnold 2009-10-10 12:41:16 UTC
*** Bug 47014 has been marked as a duplicate of this bug. ***