huxi / lilith

Lilith is a Logging- and AccessEvent viewer for Logback, log4j, log4j2 and java.util.logging
http://lilith.huxhorn.de
GNU Lesser General Public License v3.0
137 stars 18 forks source link

Unable to log with log4j2 #30

Closed Pesegato closed 7 years ago

Pesegato commented 7 years ago

First of all, the documentation is incosistent as is stated:

Lilith is listening for Log4j 2™ SocketAppender connections on port 4445. and the code below a different port

<Socket name="Socket" host="localhost" port="4560" protocol="TCP">

However, with this code:

import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.LogManager;

public class TestLog {

    private static final Logger logger = LogManager.getLogger(TestLog.class);

    public static void main(final String... args) {

        logger.trace("Entering application.");
        logger.trace("Exiting application.");
    }
}

And this configuration

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="trace">
    <Appenders>
        <Socket name="LilithDev" host="10.1.10.96" port="4560" protocol="TCP">
            <SerializedLayout />
        </Socket>
        <RollingFile name="RollingFile" fileName="/var/log/log4j2.log"
                     filePattern="/var/log/log4j2-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <Pattern>%d %p %c{1.} %C{1} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="150 kB"/>
            </Policies>
            <DefaultRolloverStrategy max="10"/>      
        </RollingFile>
        <Syslog name="Splunk" host="10.1.30.36" port="514" protocol="TCP"/>
    </Appenders>
    <Loggers>
        <Logger name="com.ups" level="trace">
        </Logger>
        <Root level="all">
            <AppenderRef ref="LilithDev"/>
            <AppenderRef ref="Splunk"/>
            <AppenderRef ref="RollingFile"/>
        </Root>
    </Loggers>
</Configuration>

Lilith 8.1 don't see anything... nor I have any lilith log that help me. I can see that the doors are open, but no connection is shown on the lilith window.

huxi commented 7 years ago

Granted, the documentation is a bit confusing. Lilith is listening on both ports, 4445 an 4560, for historic reasons.

Did you check the "Lilith events" (Ctrl-0) for suspicious entries?

Another place you could check would be USER_HOME\.lilith\errors.log.

It's also possible that your application is closing too fast. The events are sent asynchronously and may get lost if the application exits. You could add an endless loop with a log statement to your main method to test if that's the reason.

There's a "Debug..." entry in the "Help" menu. If you click on "Log all!" in the Debug dialog then this should open 10 connections to Lilith originating from itself. Does this work?

Pesegato commented 7 years ago

Nope, I'm now trying with a 10 seconds sleep...

Pesegato commented 7 years ago

To recap: lilith events shows nothing wrong errors.log shows nothing wrong I added 10 seconds sleep after logging before exiting The log all opens 10 connections to lilith

But the test case above don't log anything at all... I'm considering switching to java.util.logging :(

Pesegato commented 7 years ago

Also please note that while your documentation is for localhost logging, I'm actually doing remote logging (the host field has the IP of Lilith, but the log4j2 is on another reachable IP). Also I can confirm that the messages are sent in that I have wireshark log of them.

huxi commented 7 years ago

If the logs for the 10 debug connections are opening then we can at least be sure that Lilith itself is working. One of those debug connections is using serialized Logback events sent to port 4560 and Lilith doesn't care whether it's receiving serialized Logback, log4j or log4j2 events. It just converts the events as needed and should barf in the logs if deserialization is having any problems.

Is Lilith receiving events if you run your test app on your local machine with 127.0.0.1 as the IP?

I suspect that there is something going wrong with the Windows firewall or some other Windows security feature. I can't test this myself since I don't have access to any Windows machine.

Pesegato commented 7 years ago

Nope, I don't receive event on 127.0.0.1. If I close lilith and then run the test I get an exception "Error writing to TCP:127.0.0.1:4560 socket not available". If I run lilith and then run the test I don't get the expection (therefore the socket is receiving events), but on the gui and the error.log I see nothing, the event is silently discarded...

huxi commented 7 years ago

Hm... seriously strange...

This is what my config looks like in the sandbox:

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="debug">
    <appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} --- %msg%n"/>
        </Console>
        <Socket name="Socket" host="localhost" port="4560" protocol="TCP">
            <SerializedLayout />
        </Socket>
    </appenders>
    <loggers>
        <root level="all">
            <appender-ref ref="Console"/>
            <appender-ref ref="Socket"/>
        </root>
    </loggers>
</configuration>

... but it's exactly the same as in the README.md.

You are using Lilith 8.1.x together with log4j2 2.8.1, right?

Pesegato commented 7 years ago

I'm using lilith 8.1.0, but on the client I have Java 6 and therefore I'm forced to use log4j2 2.3 (latest available for Java 6).

When I test localhost, I use Java 8 + log4j2 2.3

huxi commented 7 years ago

Current SNAPSHOT version of Lilith would write the following to the "Lilith events":

Exception (java.io.InvalidClassException: 'org.apache.logging.log4j.core.impl.Log4jLogEvent$LogEventProxy; local class incompatible: stream classdesc serialVersionUID = -7139032940312647146, local class serialVersionUID = -8634075037355293699') while reading events. Adding eventWrapper with empty event and stopping...

Not writing anything to "Lilith events" was a bug.

I think your best bet would be to use SLF4J/Logback with my own appender. Be sure to use version 0.9.44 of the Lilith dependencies since those were the last that work with Java below 1.8. The latest Lilith version can still receive events from previous Lilith appender versions.

SLF4J 1.7.7 and Logback 1.1.2 and would be the matching dependencies guaranteed to be compatible.

There really isn't anything else I can do for you. Java Serialization is a fragile (and dangerous) beast and there is no way I'm aware of to support more than one specific version of a class at the same time.

I'm currently working on support for more log4j2 layouts (JSON, YAML, XML) but that won't benefit you either since it will need at least log4j2 2.9. It would help with issues like that in the future, though.

Pesegato commented 7 years ago

I was already using your appender, but since I also needed syslog (which logback partially support... see https://stackoverflow.com/questions/30613319/logback-tcp-syslog-conforming-rfc-5424 )

...I was trying to switch from logback to log4j2.

So at the end of the day I guess that, thanks to slf4j, I'll use logback when I need lilith appender, and log4j2 when I need syslog... can't have both. Thanks, anyway for your support.

huxi commented 7 years ago

You are welcome.