logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 53635] New: LOG4J logging does not work correctly on Solaris when the interrupted flag of the Thread is set
Date Wed, 01 Aug 2012 12:57:03 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=53635

          Priority: P2
            Bug ID: 53635
          Assignee: log4j-dev@logging.apache.org
           Summary: LOG4J logging does not work correctly on Solaris when
                    the interrupted flag of the Thread is set
          Severity: normal
    Classification: Unclassified
                OS: Solaris
          Reporter: michael@michaelmess.de
          Hardware: PC
            Status: NEW
           Version: 1.2.17
         Component: Appender
           Product: Log4j

Related LOG4J tickets: 
 * https://issues.apache.org/bugzilla/show_bug.cgi?id=44157
 * https://issues.apache.org/bugzilla/show_bug.cgi?id=47401

The interrupted state is no longer swallowed, but logging still gets corrupted
on Solaris, when the thread has the interrupt flag set while it is logging
something.

Under Linux everything works well, but under Solaris, logging output gets
corrupted.

On an earlier Log4J version we also had the issue that the interrupted flag got
cleared unexpectedly when the Thread was logging something and has been
interrupted just before logging. See related tickets above.

The test shows that it is not the case now, when the interrupted flag was set
before calling the logger, but I haven't tested yet, what happens, when the
Thread gets interrupted while it is already executing code from Log4J.
Linux was not affected.

log4j   version = 1.2.17
Solaris version = SunOS xsola07 5.10 Generic_147441-12 i86pc i386 i86pc
                  Solaris 10 10/08 s10x_u6wos_07b X86

The Logger class in this example delegates the logging to LOG4J.

NOTE: In my case the UnitTest succeeds, but logging is corrupted. Please verify
the logging output.

public class UnitTest_Logger {

    /**
     * This test tests the handling of the interrupted flag in Log4J. The
interrupted flag should not be modified during
     * logging. DEVTS-353: Test if "Failed to flush writer" issue has been
fixed: Should fail on Solaris, if the bug has
     * not been fixed. Hudson should complain on Solaris while this works under
LINUX.
     *
     * @throws Exception
     */
    @Test
    public void testLoggingWhenInterrupted()
        throws Exception {
        boolean failed = false;
        final String longString = "...";
        int counter = 0;
        final Logger myLogger = new Logger( getClass() );
        final List<String> logMessageList = new ArrayList<String>();
        Thread.interrupted(); // Clear interrupted Flag (if it was set)
        for ( int i = 1; i <= 9; i++ ) {
            final boolean interrupted = getInterrupted();
            failed |= interrupted;
            final String logmessage = ++counter + " " + interruptedString(
interrupted ) + i + longString;
            logMessageList.add( logmessage );
            myLogger.logInfo( logmessage );
        }
        Thread.currentThread().interrupt(); // Set interrupted Flag.
        for ( int i = 1; i <= 9; i++ ) {
            final boolean interrupted = getInterrupted();
            failed |= ( !interrupted );
            final String logmessage = ++counter + " " + interruptedString(
interrupted ) + i + longString;
            logMessageList.add( logmessage );
            myLogger.logInfo( logmessage );
        }
        Thread.interrupted(); // Clear interrupted Flag
        for ( int i = 1; i <= 9; i++ ) {
            final boolean interrupted = getInterrupted();
            failed |= interrupted;
            final String logmessage = ++counter + " " + interruptedString(
interrupted ) + i + longString;
            logMessageList.add( logmessage );
            myLogger.logInfo( logmessage );
        }
        assertFalse( "Interrupted flag has been modified unexpectedly.", failed
);
        myLogger.logInfo( "These messages should have been logged:" );
        for ( final String logMessage : logMessageList ) {
            myLogger.logInfo( "" + logMessage );
        }
    }



    private String interruptedString( final boolean interrupted ) {
        return interrupted ? "INTERRUPTED" : "NOT interrupted";
    }



    private boolean getInterrupted() {
        return Thread.currentThread().isInterrupted();
    }



    public static void main( final String[] args ) {
        try {
            new UnitTest_Logger().testLoggingWhenInterrupted();
        } catch ( final Exception e ) {
            throw new IllegalStateException( e );
        }
    }

}



This is the logging output from Solaris: When the Interrupted flag is set, only
one line gets logged, the rest is silently dropped.
After clearing the interrupted flag, everything works fine again.

[2012-07-31 14:43:03,877] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 1
NOT interrupted1...
[2012-07-31 14:43:03,877] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 2
NOT interrupted2...
[2012-07-31 14:43:03,877] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 3
NOT interrupted3...
[2012-07-31 14:43:03,878] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 4
NOT interrupted4...
[2012-07-31 14:43:03,878] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 5
NOT interrupted5...
[2012-07-31 14:43:03,878] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 6
NOT interrupted6...
[2012-07-31 14:43:03,878] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 7
NOT interrupted7...
[2012-07-31 14:43:03,878] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 8
NOT interrupted8...
[2012-07-31 14:43:03,879] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 9
NOT interrupted9...
[2012-07-31 14:43:03,879] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 10
INTERRUPTED1...
3,0001,3,0001,[2012-07-31 14:43:03,882] [INFO ]
[com.macd.logging.UnitTest_Logger] [main] 19 NOT interrupted1...
[2012-07-31 14:43:03,882] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 20
NOT interrupted2...
[2012-07-31 14:43:03,882] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 21
NOT interrupted3...
[2012-07-31 14:43:03,882] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 22
NOT interrupted4...
[2012-07-31 14:43:03,883] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 23
NOT interrupted5...
[2012-07-31 14:43:03,883] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 24
NOT interrupted6...
[2012-07-31 14:43:03,883] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 25
NOT interrupted7...
[2012-07-31 14:43:03,883] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 26
NOT interrupted8...
[2012-07-31 14:43:03,884] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 27
NOT interrupted9...
[2012-07-31 14:43:03,884] [INFO ] [com.macd.logging.UnitTest_Logger] [main]
These messages should have been logged:
[2012-07-31 14:43:03,884] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 1
NOT interrupted1...
[2012-07-31 14:43:03,884] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 2
NOT interrupted2...
[2012-07-31 14:43:03,885] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 3
NOT interrupted3...
[2012-07-31 14:43:03,885] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 4
NOT interrupted4...
[2012-07-31 14:43:03,885] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 5
NOT interrupted5...
[2012-07-31 14:43:03,885] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 6
NOT interrupted6...
[2012-07-31 14:43:03,885] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 7
NOT interrupted7...
[2012-07-31 14:43:03,886] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 8
NOT interrupted8...
[2012-07-31 14:43:03,886] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 9
NOT interrupted9...
[2012-07-31 14:43:03,886] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 10
INTERRUPTED1...
[2012-07-31 14:43:03,886] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 11
INTERRUPTED2...
[2012-07-31 14:43:03,886] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 12
INTERRUPTED3...
[2012-07-31 14:43:03,887] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 13
INTERRUPTED4...
[2012-07-31 14:43:03,887] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 14
INTERRUPTED5...
[2012-07-31 14:43:03,887] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 15
INTERRUPTED6...
[2012-07-31 14:43:03,887] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 16
INTERRUPTED7...
[2012-07-31 14:43:03,888] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 17
INTERRUPTED8...
[2012-07-31 14:43:03,888] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 18
INTERRUPTED9...
[2012-07-31 14:43:03,888] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 19
NOT interrupted1...
[2012-07-31 14:43:03,888] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 20
NOT interrupted2...
[2012-07-31 14:43:03,888] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 21
NOT interrupted3...
[2012-07-31 14:43:03,889] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 22
NOT interrupted4...
[2012-07-31 14:43:03,889] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 23
NOT interrupted5...
[2012-07-31 14:43:03,889] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 24
NOT interrupted6...
[2012-07-31 14:43:03,889] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 25
NOT interrupted7...
[2012-07-31 14:43:03,890] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 26
NOT interrupted8...
[2012-07-31 14:43:03,890] [INFO ] [com.macd.logging.UnitTest_Logger] [main] 27
NOT interrupted9...

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message