Gelf Appender not working when running on same machine as graylog

mp911de / logstash-gelf

Graylog Extended Log Format (GELF) implementation in Java for all major logging frameworks: log4j, log4j2, java.util.logging, logback, JBossAS7 and WildFly 8-12

http://logging.paluch.biz

MIT License

425 stars 102 forks source link

Gelf Appender not working when running on same machine as graylog #48

Closed ChristianAE closed 9 years ago

ChristianAE commented 9 years ago

I am using log4j and log4j2 in my application.

The Appender in my log4j2.xml looks like this:

<Gelf name="Gelf" host="udp:devbox" port="12202"
            extractStackTrace="true" filterStackTrace="true" maximumMessageSize="8192"
            originHost="server_dev_log4j2">
            <Field name="level" pattern="INFO" />
</Gelf>

In log4j.properties it looks like this:

log4j.appender.gelf=biz.paluch.logging.gelf.log4j.GelfLogAppender
log4j.appender.gelf.Threshold=INFO
log4j.appender.gelf.Host=udp:devbox
log4j.appender.gelf.Port=12202
log4j.appender.gelf.OriginHost=server_dev_log4j
log4j.appender.gelf.ExtractStackTrace=true
log4j.appender.gelf.FilterStackTrace=true
log4j.appender.gelf.MaximumMessageSize=8192

"devbox" is the name of the maschine (Ubuntu 14.04) running the server. The graylog server runs inside a Docker container on the same machine.

This configuration works when I start it locally(eclipse). On the server only log4j is sending logs to the graylog server. In addition to the Gelf Appender a RollingFile Appender is defined in the log4j2.xml. This works as expected.

Here the dependencies of the application:

dependencies {
    compile group: 'commons-collections', name: 'commons-collections', version: '3.2'
    compile 'biz.paluch.logging:logstash-gelf:1.6.0'
    compile 'org.eclipse.jetty:jetty-server:9.3.0.v20150612'
    compile 'org.eclipse.jetty:jetty-servlet:9.3.0.v20150612'
    compile 'org.glassfish.jersey.core:jersey-server:2.19'
    compile 'org.glassfish.jersey.containers:jersey-container-jetty-http:2.19'
    compile 'org.glassfish.jersey.containers:jersey-container-servlet:2.19'
    compile 'org.glassfish.jersey.media:jersey-media-moxy:2.19'
    compile 'org.mongodb:mongo-java-driver:3.0.2'
    compile 'com.google.code.gson:gson:2.3.1'
    compile 'org.slf4j:slf4j-log4j12:1.7.12'
    compile 'org.slf4j:jul-to-slf4j:1.7.12'
    compile 'org.apache.logging.log4j:log4j-core:2.3'
    testCompile group: 'junit', name: 'junit', version: '4.+'
}

mp911de commented 9 years ago

UDP is hard to debug, once it's not working as expected. I noticed that you used port 12202 instead of 12201, which is fine, if your server listens on 12202. I currently do not fully understand your question/scenario. AFAIK graylog also supports a TCP mode. By using TCP, network/config errors get more obvious.

It works if the app and graylog run on different hosts, right? Is graylog then running also within Docker?

You can verify the transport if you didn't already so, with this script: https://gist.github.com/gm3dmo/7721379

ChristianAE commented 9 years ago

I used TCP(on default port 12201) before trying if UDP might work.

The behavior is in both cases the same. Starting the application inside of eclipse leads to both loggers (log4j & log4j2) to send their messages to graylog. Running it on the server (the same as graylog runs on) only the log4j logger sends the logs to graylog. The graylog configuration is in both cases the same(inside a Docker container). The output of docker ps looks like this:

CONTAINER ID        IMAGE               COMMAND                CREATED             STATUS              PORTS                                                                                                                                   NAMES
77e12af07c24        graylog2/allinone   "/opt/graylog/embedd   11 hours ago        Up 4 seconds        443/tcp, 514/tcp, 0.0.0.0:9000->9000/tcp, 514/udp, 4001/tcp, 12201/udp, 0.0.0.0:12201->12201/tcp, 0.0.0.0:12202->12202/udp, 12900/tcp   fervent_mcclintock

This is the output of the gelfsender.sh

Locally:

Plain
-----
{
  "version": "1.0",
  "host": "devbox",
  "short_message": "test message short version",
  "full_message": "longer test message. dont\n worry be happy",
  "timestamp": 1437208859.N,
  "level": 1,
  "facility": "gelftester",
  "_user_id": 42,
  "_Environment": "test",
  "_AppName": "testapp"
}==============

Gzipped and Gunzipped
---------------------
{
  "version": "1.0",
  "host": "devbox",
  "short_message": "test message short version",
  "full_message": "longer test message. dont\n worry be happy",
  "timestamp": 1437208859.N,
  "level": 1,
  "facility": "gelftester",
  "_user_id": 42,
  "_Environment": "test",
  "_AppName": "testapp"
}==============

Send
----
==============

No error but also no messages arrives in graylog.

On the server using localhost as hostname

Plain
-----
{
  "version": "1.0",
  "host": "localhost",
  "short_message": "test message short version",
  "full_message": "longer test message. dont\n worry be happy",
  "timestamp": 1437208988.108591701,
  "level": 1,
  "facility": "gelftester",
  "_user_id": 42,
  "_Environment": "test",
  "_AppName": "testapp"
}==============

Gzipped and Gunzipped
---------------------
{
  "version": "1.0",
  "host": "localhost",
  "short_message": "test message short version",
  "full_message": "longer test message. dont\n worry be happy",
  "timestamp": 1437208988.108591701,
  "level": 1,
  "facility": "gelftester",
  "_user_id": 42,
  "_Environment": "test",
  "_AppName": "testapp"
}==============

Send
----

Nothing happens (I waited 4-5min).

I am a JAVA developer with only a little knowledge about network protocols. How would I debug the TCP connection?

mp911de commented 9 years ago

I'll dig in the evening into it.

Von meinem iPhone gesendet

Am 18.07.2015 um 10:46 schrieb Christian notifications@github.com:

I used TCP(on default port 12201) before trying if UDP might work.

The behavior is in both cases the same. Starting the application inside of eclipse leads to both loggers (log4j & log4j2) to send their messages to graylog. Running it on the server (the same as graylog runs on) only the log4j logger sends the logs to graylog. The graylog configuration is in both cases the same(inside a Docker container). The output of docker ps looks like this:

CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 77e12af07c24 graylog2/allinone "/opt/graylog/embedd 11 hours ago Up 4 seconds 443/tcp, 514/tcp, 0.0.0.0:9000->9000/tcp, 514/udp, 4001/tcp, 12201/udp, 0.0.0.0:12201->12201/tcp, 0.0.0.0:12202->12202/udp, 12900/tcp fervent_mcclintock This is the output of the gelfsender.sh

Locally:

Plain

{ "version": "1.0", "host": "devbox", "short_message": "test message short version", "full_message": "longer test message. dont\n worry be happy", "timestamp": 1437208859.N, "level": 1, "facility": "gelftester", "_user_id": 42, "_Environment": "test", "_AppName": "testapp" }==============

Gzipped and Gunzipped

{ "version": "1.0", "host": "devbox", "short_message": "test message short version", "full_message": "longer test message. dont\n worry be happy", "timestamp": 1437208859.N, "level": 1, "facility": "gelftester", "_user_id": 42, "_Environment": "test", "_AppName": "testapp" }==============

Send

No error but also no messages arrives in graylog.

On the server using localhost as hostname

Plain

{ "version": "1.0", "host": "localhost", "short_message": "test message short version", "full_message": "longer test message. dont\n worry be happy", "timestamp": 1437208988.108591701, "level": 1, "facility": "gelftester", "_user_id": 42, "_Environment": "test", "_AppName": "testapp" }==============

Gzipped and Gunzipped

{ "version": "1.0", "host": "localhost", "short_message": "test message short version", "full_message": "longer test message. dont\n worry be happy", "timestamp": 1437208988.108591701, "level": 1, "facility": "gelftester", "_user_id": 42, "_Environment": "test", "_AppName": "testapp" }==============

Send ----``` Nothing happens (I waited 4-5min).

I am a JAVA developer with only a little knowledge about network protocols. How would I debug the TCP connection? — Reply to this email directly or view it on GitHub.

ChristianAE commented 9 years ago

Just as additional information the configuration of the Input in graylog:

TCP:

    recv_buffer_size: 1048576
    port: 12201
    tls_key_file:
    tls_key_password: *******
    use_null_delimiter: true
    max_message_size: 2097152
    override_source:
    bind_address: 0.0.0.0
    tls_cert_file:

UDP

    override_source:
    recv_buffer_size: 16384
    port: 12202
    bind_address: 0.0.0.0

If you need any further information or want me to run any tests just let me know. But I might not get back before tomorrow evening.

mp911de commented 9 years ago

Thanks for the update and sorry for misleading you. The script from above did not work for me either. So, if log4j 1.2 works and log4j 2.3 not, it's not a network issue. About the TCP issue: Change your log4j2 config to:

<Gelf name="Gelf" host="tcp:devbox" port="12201"
            extractStackTrace="true" filterStackTrace="true" maximumMessageSize="8192"
            originHost="server_dev_log4j2">
            <Field name="level" pattern="INFO" />
</Gelf>

to give it a try.

I checked with boot2docker and it's working for me. I used a very simple setup with a main and just a bunch of jars:

json-simple-1.1.1.jar
log4j-api-2.3.jar
log4j-core-2.3.jar
logstash-gelf-1.6.0.jar
log4j2.xml
TestMyLogger.java

and a simple log4j2 config. I shared it at https://www.dropbox.com/s/o2a216kc08ah4e8/log4j2-test.zip?dl=0

I currently have no real clue about the reason. Enable log4j2's config debug logging by setting

<Configuration status="debug" strict="true">

and check the logs please. Then you should see a line like

2015-07-18 21:56:04,634 DEBUG Found factory method [createAppender]: public static biz.paluch.logging.gelf.log4j2.GelfLogAppender ...

A good test, to check, whether the appender is used is by just using an invalid host name and that should cause two log line:

2015-07-18 21:56:04,641 ERROR Unknown GELF server hostname:udp:devbox

and later on

2015-07-18 21:56:04,654 ERROR Could not send GELF message

ChristianAE commented 9 years ago

Hey,

I think I got a step closer to the solution. I altered my log4j2.xml as suggested. Locally I now get a whole bunch of additional logging.

On the server itself I don't. This hints to some kind of problem regarding the log4j2.xml file. It seems like it is not completely ignored since logging to the file works as expected.

So it looks like a problem in how I pack the application? I'm using gradle to create an (Uber)jar which I than run on the server.

Again locally everything works as expected.

Here the complete config files. log4j:

# Basic Log4j Configuration with STDOUT and File logging
log4j.rootLogger=INFO, console, file, gelf

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{HH:mm:ss.SSS} - %-5p - %m -> [%l]%n

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{HH:mm:ss.SSS} - %-5p - %m -> [%l]%n
log4j.appender.file.File=${app_home}/logs/app.log
log4j.appender.file.MaxFileSize=10MB
log4j.appender.file.MaxBackupIndex=4
log4j.appender.file.append=true

log4j.appender.gelf=biz.paluch.logging.gelf.log4j.GelfLogAppender
log4j.appender.gelf.Threshold=INFO
log4j.appender.gelf.Host=tcp:127.0.0.1
log4j.appender.gelf.Port=12201
log4j.appender.gelf.OriginHost=server_dev_log4j
log4j.appender.gelf.ExtractStackTrace=true
log4j.appender.gelf.FilterStackTrace=true
log4j.appender.gelf.MaximumMessageSize=8192

log4j2:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" strict="true">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} - %-5p - %m - [%l]%n" />
        </Console>
        <RollingFile name="RollingFile" fileName="${app_home}/logs/app.log"
            filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <Pattern>%d{HH:mm:ss.SSS} - %-5p - %m - [%l]%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="10 MB" />
            </Policies>
            <DefaultRolloverStrategy max="20" />
        </RollingFile>
        <Gelf name="Gelf" host="tcp:127.0.0.1" port="12201"
            extractStackTrace="true" filterStackTrace="true" maximumMessageSize="8192"
            originHost="server_dev">
            <Field name="level" pattern="INFO" />
        </Gelf>
    </Appenders>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="Console" />
            <AppenderRef ref="RollingFile" />
            <AppenderRef ref="Gelf" />
        </Root>
    </Loggers>
</Configuration>
``

mp911de commented 9 years ago

Perhaps there is another log4j2 config. Check the log4j2 config guide: https://logging.apache.org/log4j/2.x/manual/configuration.html

You should be careful with the uberjar-thing and log4j2. Log4j2 uses a discovery mechanism (it's not magic, but almost) for its plugin mechanism to look up handlers. I'm not sure, what happens, if there are many log4j2 archives, but for sure nothing very desirable. There are also some threads about that topic: http://stackoverflow.com/questions/31341285/spring-boot-custom-logger-log4j2

ChristianAE commented 9 years ago

Another step closer.

Starting it on the console with I get this ouput:

2015-07-19 21:26:05,906 DEBUG Still building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin]. Searching for factory method...
2015-07-19 21:26:05,906 DEBUG Found factory method [createAppenders]: public static java.util.concurrent.ConcurrentMap org.apache.logging.log4j.core.config.AppendersPlugin.createAppenders(org.apache.logging.log4j.core.Appender[]).
2015-07-19 21:26:05,907 ERROR Appenders contains an invalid element or attribute "Gelf"
2015-07-19 21:26:05,907 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.AppendersPlugin for element Appenders with params(={Console, RollingFile})

Sadly no further information why the "element or attribute" Gelf is invalid.

mp911de commented 9 years ago

Because Gelf cannot be resolved to a log4j2 handler/factory. I guess, you need to run the org.apache.logging.log4j.core.config.plugins.processor.PluginProcessor to re-generate the META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat. This would require packaging all dependencies, invoking the annotation processor (PluginProcessor) and re-packaging your jar.

There's already an open issue: https://issues.apache.org/jira/browse/LOG4J2-1059

ChristianAE commented 9 years ago

From what I understand not packaging it as an UbarJar might resolve the problem?

Since I use Gradle to build it I really don't care if the result is just one jar or the dependencies come outside of it.

mp911de commented 9 years ago

Give it a try.

ChristianAE commented 9 years ago

Thanks for your help. Since it is a dependency issues as far as I'm concerned this issue can be closed.

Thanks for your help!

mp911de commented 9 years ago

You're welcome.