Search code examples
loggingjava-ee-6glassfish-3logbackweblogic12c

logback-classic SocketAppender and Lilith log viewer

In a JEE6 project deployed in glassfish 3.1. I have the following issue:

Lilith - a logviewer which listens to a socket - only catches the first log message then misses the rest of the messages. What makes it even worse is that the behavior is not consistent and occasionally it might catch the first and the third message. I can not find a pattern in the behavior, so any comments might help me find a way out!

Given logback.xml:

    <configuration scan="true" scanPeriod="3 seconds">

    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"/>

    <appender name="LogbackClassic" class="ch.qos.logback.classic.net.SocketAppender"> 
        <RemoteHost>localhost</RemoteHost> 
        <Port>4560</Port> 
        <ReconnectionDelay>170</ReconnectionDelay> 
        <IncludeCallerData>true</IncludeCallerData> 
    </appender>

    <appender name="FILE"
          class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>log/prototype1.log</File>
        <rollingPolicy
        class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>
                logFile.%d{yyyy-MM-dd_HH-mm}.log.zip
            </FileNamePattern>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>
                %d{HH:mm:ss.SSS} %-5p %F:%L %C %M %c - %m%n
            </Pattern>
        </encoder>
    </appender>

    <logger name="com.sam.prototype1" level="DEBUG"> 
        <appender-ref ref="FILE"/>
        <appender-ref ref="LogbackClassic"/> 
    </logger>

</configuration>

And given the class:

@RequestScoped
@Named
public class TimeProperty {

    @Inject
    private Date date;
    @Inject
    private SimpleDateFormat dateFormat;
    @Inject
    @LogbackLogger 
    private Logger logger;

    private String time;

    public String getTime() {
        return time;
    }

    public void setTime(String timeParam) {
        logger.debug("First log message ");
        dateFormat.applyPattern("HH:mm:ss:SSS");
        String tmp = dateFormat.format(date.getTime());
        logger.debug("Second log message: Logged time= "+tmp);
        time = tmp;
        logger.debug("Third log message: Logged time");
    }
    public void callSetTime(){
        setTime("Dummy parameter to avoid NULL in the test");
    }
}

which is triggered using the following jsf web page:

<!DOCTYPE html>
<html xmlns="http://www.w3.org/1999/xhtml">
    <head>
        <title>Time Page</title>
    </head>
    <body>
        #{timeProperty.callSetTime()}
    </body>
</html>

The file log/prototype1.log receives the following lines:

17:40:45.479 DEBUG TimeProperty.java:38 com.sam.prototype1.modelentities.TimeProperty setTime com.sam.prototype1.modelentities.TimeProperty - First log message 
17:40:45.498 DEBUG TimeProperty.java:41 com.sam.prototype1.modelentities.TimeProperty setTime com.sam.prototype1.modelentities.TimeProperty - Second log message: Logged time= 17:40:45:114
17:40:45.499 DEBUG TimeProperty.java:44 com.sam.prototype1.modelentities.TimeProperty setTime com.sam.prototype1.modelentities.TimeProperty - Third log message: Logged time

Meanwhile Lilith receives only the first message:

Lilith snapshot

As an extra given for your convenience, here is the POM.xml:

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
     xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>

<groupId>com.sam</groupId>
<artifactId>Prototype1</artifactId>
<version>1.0-SNAPSHOT</version>
<packaging>war</packaging>

<name>Prototype1</name>

<properties>
    <endorsed.dir>${project.build.directory}/endorsed</endorsed.dir>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
</properties>

<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.5</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.0.13</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.0.13</version>
    </dependency>
    <dependency>
        <groupId>javax</groupId>
        <artifactId>javaee-web-api</artifactId>
        <version>6.0</version>
        <scope>provided</scope>
    </dependency>
</dependencies>

<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <version>3.1</version>
            <configuration>
                <source>1.6</source>
                <target>1.6</target>
                <compilerArguments>
                    <endorseddirs>${endorsed.dir}</endorseddirs>
                </compilerArguments>
            </configuration>
        </plugin>
</project>

Needless to mention:

I also satisfied Glassfish requirement to add the following files to the domain classpath: jul-to-slf4j-1.7.5.jar and slf4j-api-1.7.5 and logback-core-1.0.13.jar and logback-classic-1.0.13.jar

Solution

  • Please try again with Logback 1.1.1 and SLF4J 1.7.6.

    http://logback.qos.ch/news.html states that Logback 1.1.1 includes a fix for dropped events related to SocketAppender.