Log4j SocketAppender. Logstash : tcp input --> OK, log4j input --> KO - SOLVED


(Tur) #1

Hello there,

I am currently facing an issue when using SocketAppender in Log4j (v1.2) with log4j input in Logstash (v2.1).
Issue is simple, I configured Log4j like this :

Log4jConfiguration.xml :

< log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    < appender class="org.apache.log4j.net.SocketAppender" name="SocketAppender">
        < param name="RemoteHost" value="LOGSERVER"/>
        < param name="Port" value="3518"/>
    < /appender>
    < category name="com.eibus.management.AlertSystem">
        < priority value="info"/>
        < appender-ref ref="SocketAppender"/>
    < /category>
    < root>
        < priority value="info"/>
        < appender-ref ref="SocketAppender"/>
    < /root>
< /log4j:configuration>

On the LOGSERVER server, the logstash configuration is the following one :

Logstash.conf :

input {
    # Input for the logs sent via SocketAppender in Log4j - TEST
    log4j {
        port => 3518
        type => "LOG4JEvent"
    }
}
output {
    file {
        codec => "json"
        path => "DEBUG.json"
    }
}

With this configuration, the log file DEBUG.json is not created.
The debug_logstash.log file is created but there is no entry.

Then I tried by just changing log4j input by tcp one :

input {
    tcp{
        port => 3518
        type => "LOG4JEvent"
    }
}

In that case, the DEBUG.json file is created and filled with entry such as :
{"message":"blablabla","@version":"1","@timestamp":"2015-12-02T12:42:48.475Z","host":"10.xxx.yyy.zzz","type":"LOG4JEvent"}

And debug_logstash.log is filled with entry like this :
{:timestamp=>"2015-12-02T12:42:48.472000+0000", :message=>"Received an event that has a different character encoding than you configured.", :text=>"blablabla", :expected_charset=>"UTF-8", :level=>:warn}

I verified that the log4j input is well installed by launching the "plugin list" command and I found "logstash-input-log4j" in the list.

For information, the Logstash service is launched by using NSSM with the following batch script :
@echo off
cd E:\App\ELK\ELK_Update\logstash-2.1.0\bin
set LS_MAX_MEM=256m
set JAVA_HOME=C:\Progra~1\Java\jre7
logstash agent -f logstash.conf -l debug_logstash.log

Now I am stuck... I don't know what I am missing. Is there any installation step I forgot ?
Thank you in advance for your help.

Maxime


(Mikhail) #2

Logstash 2.1 doesn't support java 1.7.
Try to use 1.8 instead.

Try to change your config as follows:

Using this output you'll get another logstash.stdout and might see more logstash logging info.


(Tur) #3

Thanks for your quick answer.
I will add JRE8 and keep you updated if there is any improvement.
But any explanation why tcp input is working even if I am using JRE7 ?

I have also checked the following URL and Logstash 2.1 seems to be compatible with Java 1.7.

By using stdout, I have the following log when running logstash :
http://www.hostpic.org/images/1512022102160102.jpg

I don't know from where the Java 1.6 reference comes...


(Mikhail) #4

I assume it is somewhere in your %PATH% environment variable.


(Tur) #5

I have just install last Java 1.8 as suggested.

When launching the logstash application, I have no more error :

But when using log4j input, there is no entry in my ouput file (the file is not created at all whereas it is when using tcp input).

Nevertheless, by using netstat -a command, I can see that connections are UP on tcp/3518 with the monitored server (but can't explain why multiple) :

What can be the next step of investigation ?


(Tur) #6

I don't know if this can help but please find below an example of the logs generated by Log4j API on the monitored server (from a FileAppender) :

< log4j:event logger="com.eibus.soap.ProcessStreamsHandler" timestamp="1449045947205" level="ERROR" thread="Monitor Stream Reader Thread">
< log4j:message></log4j:message>
< log4j:MDC></log4j:MDC>
< log4j:locationInfo class="com.eibus.soap.ProcessStreamsHandler" method="startProcessor" file="ProcessStreamsHandler.java" line="638"/>
< /log4j:event>

TO SUMMARIZE :

  • On monitored server, I am using the SocketAppender from Log4j API v1 which is working.
  • On centralized server (which host ELK) :
  • Java 1.8 is installed and JAVA_HOME is well defined.
  • tcp input is working as Logstash is receiving the logs. The output file is created and filled with the logs.
  • Issue with log4j input : the output file is not created (and, so, no log received). By using stdout output, there is no error message.

(Tur) #7

Last update :

I launched logstash with the --debug parameter and I got the following output :

In the LSoutput.txt file I can find the following message :

message=>"Plugin not defined in namespace, checking for plugin file", :type=>"input", :name=>"log4j", :path=>"logstash/inputs/log4j"

For information, I installed Logstash 2.1.0 (All Plugins) in parallel of a Logstash 1.4 installation.

Is there any environment variable to change ?


(Tur) #8

UP - Any advice or help ?
Thank in advance.


#9

Hi, sorry that you are having a hard time with log4j input.

From your last message, I suppose you are using the Elasticsearch output that is loading the elasticsearch jar and its log4j dependency => this is the reason of these log4j:WARN
Seeing your config, or at least the used plugins list could help

For the moment I cannot reproduce your error of the plugin not being found. Did you alter the logstash directory after unzip.

As I'm not on windows, the issue could come from the start scripts.
Could you try to start logstash from its main folder using the command bin\logstash.bat in case there would be a relative path that would be falsy defined.


(Tur) #10

Hi wiibaa !

I think I am not far from resolution... I keep hope.

I have installed Logstash 2.1 with all the plugins from this link ; so logstash-input-log4j is part of the list.
I have removed the elasticsearch output and I am currently using only the file output first. I want to focus on the resolution of the log4j input.

Currently my config is the following one :

################################################################################

Inputs

################################################################################

input {
log4j {
host => "localhost"
type => "LOG4JEvent"
port => 3518
mode => "server"
}
}

################################################################################

Filters

################################################################################

filter {

}

################################################################################

Outputs

################################################################################

output {
file {
path => "Output.txt"
}
}

I didn't change the Logstash directory after unzip.

I am launching Logstash as a service by using the Non-Sucking Service Manager (NSSM).
NSSM is configured as shown below :

It runs the following startLogstashService.bat script :

REM This script is used by the NSSM tool to run Logstash as a service

@echo off
cd E:\App\ELK\ELK_Update\logstash-2.1.0\bin
set LS_MAX_MEM=256m
set JAVA_HOME=C:\Progra~1\Java\jre1.8.0_65
logstash agent -f logstash.conf --debug > Debug.txt


(Tur) #11

No more tracks ?
So I guess the next step will be to re-perform a complete installation.


#12

Sorry I'm not familiar with NSSM but I insist that the bin folder should not be the starting directory it might have impact even if it should not.
Did you look to other Logstash/NSSM tentative like https://raw.githubusercontent.com/verbosemode/public-notes/master/logstash-windows.md where they define the logstash installation main folder as the application directory and not the bin/ folder


(Tur) #13

I have changed the starting directory as described in the link you provided.
My folder E:/App/ELK/logstash-2.1.1/ now contains, the installation folder (/install), the NSSM folder (/nssm) and the logstach configuration file (logstash.conf).

NSSM Stdout :
io/console not supported; tty will not be manipulated log4j:WARN No appenders could be found for logger (org.apache.http.impl.conn.PoolingHttpClientConnectionManager). log4j:WARN Please initialize the log4j system properly. log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

Logstash debug :
message=>"Plugin not defined in namespace, checking for plugin file", :type=>"input", :name=>"log4j", :path=>"logstash/inputs/log4j"

Except the above messages, I can see by using "netstat -a" command that the communication are established on my tcp port...


(Tur) #14

Hello... No improvement so far...
The last configuration I have setup is the following one.

  • On the monitored host :

log4jconfiguration.xml :

  • On the centralized server :

Logstash.conf :

input {
log4j {
mode => server
host => "0.0.0.0"
port => 4560
type => "LOG4JEvent"
}
}
output {
file {
path => "LS_Output.txt"
}
}

Starting logstash :
logstash agent --debug -f ../../logstash.conf >> DEBUG.log

Netstat -a :

But I still don't have LS_Output.txt file whereas it is created when using tcp input...


(Tur) #15

DEBUG.log part #1 :

{:timestamp=>"2015-12-16T09:40:51.560000+0000", :message=>"Reading config file", :config_file=>"E:/App/ELK/logstash-2.1.1/logstash.conf", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/agent.rb", :line=>"325", :method=>"local_config"}
{:timestamp=>"2015-12-16T09:40:51.640000+0000", :message=>"Compiled pipeline code:\n        @inputs = []\n        @filters = []\n        @outputs = []\n        @periodic_flushers = []\n        @shutdown_flushers = []\n\n          @input_log4j_1 = plugin(\"input\", \"log4j\", LogStash::Util.hash_merge_many({ \"mode\" => (\"server\") }, { \"host\" => (\"0.0.0.0\") }, { \"port\" => 4560 }, { \"type\" => (\"LOG4JEvent\") }))\n\n          @inputs << @input_log4j_1\n\n          @output_file_2 = plugin(\"output\", \"file\", LogStash::Util.hash_merge_many({ \"path\" => (\"LS_Output.txt\") }))\n\n          @outputs << @output_file_2\n\n  def filter_func(event)\n    events = [event]\n    @logger.debug? && @logger.debug(\"filter received\", :event => event.to_hash)\n    events\n  end\n  def output_func(event)\n    @logger.debug? && @logger.debug(\"output received\", :event => event.to_hash)\n    @output_file_2.handle(event)\n    \n  end", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/pipeline.rb", :line=>"38", :method=>"initialize"}
{:timestamp=>"2015-12-16T09:40:51.643000+0000", :message=>"Plugin not defined in namespace, checking for plugin file", :type=>"input", :name=>"log4j", :path=>"logstash/inputs/log4j", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/plugin.rb", :line=>"76", :method=>"lookup"}
{:timestamp=>"2015-12-16T09:40:51.675000+0000", :message=>"Plugin not defined in namespace, checking for plugin file", :type=>"codec", :name=>"plain", :path=>"logstash/codecs/plain", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/plugin.rb", :line=>"76", :method=>"lookup"}

(Tur) #16

DEBUG.log part #2 :

{:timestamp=>"2015-12-16T09:40:51.696000+0000", :message=>"config LogStash::Codecs::Plain/@charset = \"UTF-8\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.706000+0000", :message=>"config LogStash::Inputs::Log4j/@mode = \"server\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.707000+0000", :message=>"config LogStash::Inputs::Log4j/@host = \"0.0.0.0\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.709000+0000", :message=>"config LogStash::Inputs::Log4j/@port = 4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.714000+0000", :message=>"config LogStash::Inputs::Log4j/@type = \"LOG4JEvent\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.717000+0000", :message=>"config LogStash::Inputs::Log4j/@codec = <LogStash::Codecs::Plain charset=>\"UTF-8\">", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.719000+0000", :message=>"config LogStash::Inputs::Log4j/@add_field = {}", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.723000+0000", :message=>"config LogStash::Inputs::Log4j/@data_timeout = 5", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.728000+0000", :message=>"Plugin not defined in namespace, checking for plugin file", :type=>"output", :name=>"file", :path=>"logstash/outputs/file", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/plugin.rb", :line=>"76", :method=>"lookup"}
{:timestamp=>"2015-12-16T09:40:51.741000+0000", :message=>"Plugin not defined in namespace, checking for plugin file", :type=>"codec", :name=>"json_lines", :path=>"logstash/codecs/json_lines", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/plugin.rb", :line=>"76", :method=>"lookup"}
{:timestamp=>"2015-12-16T09:40:51.767000+0000", :message=>"config LogStash::Codecs::JSONLines/@charset = \"UTF-8\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.777000+0000", :message=>"config LogStash::Codecs::Line/@charset = \"UTF-8\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.794000+0000", :message=>"config LogStash::Outputs::File/@path = \"LS_Output.txt\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.795000+0000", :message=>"config LogStash::Outputs::File/@codec = <LogStash::Codecs::JSONLines charset=>\"UTF-8\">", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.800000+0000", :message=>"config LogStash::Outputs::File/@workers = 1", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.865000+0000", :message=>"config LogStash::Outputs::File/@flush_interval = 2", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}

(Tur) #17

DEBUG.log part #3 :

{:timestamp=>"2015-12-16T09:40:51.867000+0000", :message=>"config LogStash::Outputs::File/@gzip = false", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.868000+0000", :message=>"config LogStash::Outputs::File/@filename_failure = \"_filepath_failures\"", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.870000+0000", :message=>"config LogStash::Outputs::File/@create_if_deleted = true", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/config/mixin.rb", :line=>"122", :method=>"config_init"}
{:timestamp=>"2015-12-16T09:40:51.888000+0000", :message=>"Starting Log4j input listener", :address=>"0.0.0.0:4560", :level=>:info, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"70", :method=>"register"}
{:timestamp=>"2015-12-16T09:40:51.900000+0000", :message=>"Log4j input", :level=>:info, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"73", :method=>"register"}
{:timestamp=>"2015-12-16T09:40:51.902000+0000", :message=>"Pipeline started", :level=>:info, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-core-2.1.1-java/lib/logstash/pipeline.rb", :line=>"109", :method=>"run"}
{:timestamp=>"2015-12-16T09:40:59.988000+0000", :message=>"Accepted connection", :client=>"10.xxx.xxx.xxx:64935", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"158", :method=>"run"}
{:timestamp=>"2015-12-16T09:41:04.299000+0000", :message=>"Accepted connection", :client=>"10.xxx.xxx.xxx:64951", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"158", :method=>"run"}
{:timestamp=>"2015-12-16T09:41:04.802000+0000", :message=>"Accepted connection", :client=>"10.xxx.xxx.xxx:64957", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"158", :method=>"run"}
{:timestamp=>"2015-12-16T09:41:06.286000+0000", :message=>"Accepted connection", :client=>"10.xxx.xxx.xxx:64964", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"158", :method=>"run"}
{:timestamp=>"2015-12-16T09:41:10.994000+0000", :message=>"Closing connection", :client=>"10.xxx.xxx.xxx:64935", :exception=>#<NameError: com.eibus.util.logger.Severity>, :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"111", :method=>"handle_socket"}
{:timestamp=>"2015-12-16T09:41:55.984000+0000", :message=>"Accepted connection", :client=>"10.xxx.xxx.xxx:65117", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"158", :method=>"run"}
{:timestamp=>"2015-12-16T09:41:55.993000+0000", :message=>"Closing connection", :client=>"10.xxx.xxx.xxx:65117", :exception=>#<NameError: com.eibus.util.logger.Severity>, :level=>:debug, :file=>"/App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb", :line=>"111", :method=>"handle_socket"}

#18

HAHA !!

Can you confirm that you are using a custom implementation of log4j Logger http://bpm.sihuatech.com/cordys/documentation/onlinehelp/html/javadoc/com/eibus/util/logger/CordysLogger.html

The explanation is that log4j socket appender is using JAVA serialization, so the same library must be loaded on the client side in order to de-serialize the object, thus it is failing in your case. I admit this is really not obvious !

There is currently no configuration to load additional jar for the log4j input, however you could try to hack the file located in /App/ELK/logstash-2.1.1/install/vendor/bundle/jruby/1.9/gems/logstash-input-log4j-2.0.4-java/lib/logstash/inputs/log4j.rb and add a line like require 'E:/path/to/CordysLog.jar' below the require 'java' line
to confirm this would actually fix your issue.


(Tur) #19

I have to admit that I am not very familiar with the custom configuration setup around the Cordys application to monitor. I just know that it is using the Log4j v1.2.15 and upgrading to Log4j2 is a tricky thing.

Do I have to add require 'E:\Cordys Jars\log4j-1.2.15.jar in the log4j.rb file ?

EDIT:
I have just tried by updating the log4j.rb file :

But I am still receiving the same exception error message and the output file is not created.


#20

Log4j 1.2.x is not the problem and Log4j2 is out of the topic.
It is the other way around. As the Cordys platform is extending the log4j 1.2.x library, you must find out the jar containing the following package and classes http://bpm.sihuatech.com/cordys/documentation/onlinehelp/html/javadoc/com/eibus/util/logger/package-summary.html

And this jar must be required here.
As the solution is does not seem open source, I cannot easily google for more info. Is there some cordys SDK or libraries available to you ?


Logstash - Level deserialization failed - SOLVED