Migrate Logstash to Log4j2 Logging #5651

talevy · 2016-07-19T18:19:52Z

Meta issue describing this issue: #5650

*_Quoted from the meta issue*_

Goal:

Unify logging across Logstash's Java and Ruby code.
Support changing logging level dynamically at runtime through REST endpoints
Support complete JSON logging
Provide a strategy for reading in its own JSON logs as input for self monitoring

Proposed Implementation:
Migrate from Cabin to Log4j2 as the logging library for Logstash Core and its plugins.

Reason for library change:
Logstash and its plugin's usage of Java libraries that use Log4j/SLF4j is growing. This is leading to un-captured logging by core as it is running the pipeline. Cabin is the current logging library used by Logstash, but it's support for these java libraries is limited. Configuration of these java loggers is also not managed by Logstash natively, this yields confusing warning messages when using specific plugins, like Kafka. Even Logstash's core (Logstash Event in Java) is straying away from Cabin-friendly logging land.

fbaligand · 2016-07-19T22:00:27Z

Hi,
Impressive work !

Just a remark : I think that ExampleEvent.java and Main.java should be in src/test/java folder.
It's not intended for logstash runtime use.

fbaligand · 2016-07-19T22:12:06Z

logstash-core/src/main/java/org/logstash/log/StructuredMessage.java

+import java.util.HashMap;
+import java.util.Map;
+
+@JsonSerialize(using = CustomLogEventSerializer.class)


It seems that annotation @JsonSerialize(using = CustomLogEventSerializer.class) is not useful here.

true, the current state of the code is part exploratory. so there are lingering paths of code that may or may not be necessary in the next revision

suyograo · 2016-08-11T16:13:09Z

@talevy can you fix the tests?

ph · 2016-08-11T18:05:28Z

Gemfile

+gem "webrick", ">= 0"
+gem "poseidon", ">= 0"
+gem "snappy", ">= 0"
+gem "webmock", "~> 1.21.0"


this is probably left from installing something, let make sure we dont merge it in master.

ph · 2016-08-11T20:20:51Z

@talevy I did a first pass looking great so far, before I test it manually I think the next would be:

Revert the symbols changes
Revert the self changes

Theses two things will greatly reduce the size of the PR.

ph · 2016-08-24T19:45:05Z

I have tested this PR with the logstash-input-beats, this plugin is mostly written in Java and it uses log4j2 as the logging mechanism. When I tried to use the plugin with this PR I get the following exception:

[2016-08-24T15:33:30,569][ERROR][logstash.pipeline        ] A plugin had an unrecoverable error. Will restart this plugin.
  Plugin: <LogStash::Inputs::Beats port=>5044, id=>"c68d509166089e1ac514c2a813ab45d5e0db306a-1", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_b7cc8afd-762e-4cfa-9c7b-c39c35a88d96", enable_metric=>true, charset=>"UTF-8">, host=>"0.0.0.0", ssl=>false, ssl_verify_mode=>"none", include_codec_tag=>true, ssl_handshake_timeout=>10000, congestion_threshold=>5, target_field_for_codec=>"message", tls_min_version=>1, tls_max_version=>1.2, cipher_suites=>["TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA38", "TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384", "TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256", "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256", "TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384", "TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384", "TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256"], client_inactivity_timeout=>15>
  Error: must log key-value pairs
  Exception: Java::JavaLang::IllegalArgumentException
  Stack: org.logstash.log.StructuredMessage.<init>(org/logstash/log/StructuredMessage.java:31)
org.logstash.log.StructuredMessageFactory.newMessage(org/logstash/log/StructuredMessageFactory.java:23)
org.apache.logging.log4j.spi.MessageFactory2Adapter.newMessage(org/apache/logging/log4j/spi/MessageFactory2Adapter.java:49)
org.apache.logging.log4j.spi.AbstractLogger.logMessage(org/apache/logging/log4j/spi/AbstractLogger.java:2004)
org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(org/apache/logging/log4j/spi/AbstractLogger.java:1876)
org.apache.logging.log4j.spi.AbstractLogger.info(org/apache/logging/log4j/spi/AbstractLogger.java:1421)
org.logstash.beats.Server.listen(org/logstash/beats/Server.java:59)
java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:483)
RUBY.run(/Users/ph/es/logstash-plugins/logstash-input-beats/lib/logstash/inputs/beats.rb:177)
RUBY.inputworker(/tmp/logstash/logstash-core/lib/logstash/pipeline.rb:336)

if you look at the beats code this is due of the usage of string interpolation. see https://github.com/logstash-plugins/logstash-input-beats/blob/master/src/main/java/org/logstash/beats/Server.java#L59

  logger.info("Starting server on port: {}", this.port);

We love structured log, since I control this library I can rewrite all the statements using the StructuredMessage, but this won't be the case for all the other library we will be using, BTW also I am passing our logger to the netty frameworks to get more detailled information about SSL error/Problems with frames.

@talevy Can we find an elegant solution for that?

ph · 2016-08-24T20:09:14Z

#4820 introduced --log-in-json which allow us to write log in the json format.

The refactor of the runner to use the new settings class changes that for --log.format json

Using this command with the current PR doesnt seems to do anything? Can we add back the support?

bin/logstash -f ~/es/logstash/ls_tools/beats.conf --log.format json

ph · 2016-08-24T20:15:01Z

Other than the 2 previous comment, we are really close to get this merged

suyograo · 2016-08-24T20:22:52Z

@ph @talevy how about restoring --log-in-json in a subsequent PR?

ph · 2016-08-24T20:29:54Z

@suyograo I am OK to have another PR to add the --log-in-json.

fbaligand · 2016-08-25T06:32:08Z

logstash-core/src/main/java/org/logstash/log/StructuredMessageFactory.java

+            return new StructuredMessage(message, params);
+        } else {
+            return new ParameterizedMessage(message, params);
+        }


Now that the returned Message instance is not always a StructuredMessage, it's maybe relevant to rename this class to something like LogstashMessageFactory ?

yes. I'll update

fbaligand · 2016-08-25T07:16:28Z

logstash-core/src/main/resources/log4j2.component.properties

@@ -0,0 +1,2 @@
+Log4jLogEventFactory=org.logstash.log.LogstashLogEventFactory
+log4j2.messageFactory=org.logstash.log.LogstashMessageFactory


Nice ! 👍

fbaligand · 2016-08-25T10:04:15Z

@talevy Nice remove 👍

ph · 2016-08-25T12:35:38Z

@talevy @fbaligand I've gone through the last iteration of this PR and it fixed all the issues we had with string interpolation.

The only thing I've noticed is the unchecked warning, we might want to suppress that warning.

:compileJavaNote: /private/tmp/logstash/logstash-core/src/main/java/org/logstash/log/StructuredMessage.java uses unchecked or unsafe operations.

ph · 2016-08-25T12:42:18Z

Fix the unchecked warning and it LGTM. Lets get this into master and continue on the other tasks from #5650

Amazing work @talevy!

talevy · 2016-08-25T15:37:55Z

thanks. I added a SuppressWarning for the cast that was going on. should disappear now

ph · 2016-08-25T16:23:59Z

LGTM

talevy · 2016-08-25T17:32:49Z

finally! thanks @fbaligand, @ph, and @jordansissel for the reviews! I will follow-up with some items left over now. the meta issue should have captured all the points in checkpoints and/or PRs: #5650.

Migrate to use Log4j2 for Logstash logging

talevy added v5.0.0-beta1 logging improvements labels Jul 19, 2016

talevy mentioned this pull request Jul 19, 2016

[META] Log4j2 logging in core #5650

Closed

19 tasks

fbaligand reviewed Jul 19, 2016
View reviewed changes

talevy force-pushed the feature/log4j2-logging branch from 99dcea0 to d33244a Compare July 27, 2016 23:47

talevy force-pushed the feature/log4j2-logging branch 2 times, most recently from e090a31 to c09b843 Compare August 9, 2016 20:33

suyograo assigned ph and jordansissel Aug 11, 2016

ph reviewed Aug 11, 2016
View reviewed changes

talevy force-pushed the feature/log4j2-logging branch from 646680a to 065461c Compare August 24, 2016 19:30

remove API logging prototype

1f7f4bf

bring back parameterized logging compatibility

8fefb35

fbaligand reviewed Aug 25, 2016
View reviewed changes

cleanup

165415a

fbaligand reviewed Aug 25, 2016
View reviewed changes

remove context selector

1e450a5

add unchecked cast warning suppression

4cc0bda

talevy merged commit 1b2f7a7 into master Aug 25, 2016

talevy deleted the feature/log4j2-logging branch August 25, 2016 17:30

talevy restored the feature/log4j2-logging branch August 25, 2016 17:43

suyograo pushed a commit that referenced this pull request Aug 26, 2016

Migrate Logstash to Log4j2 Logging (#5651)

b545b83

Migrate to use Log4j2 for Logstash logging

		@@ -0,0 +1,2 @@
		Log4jLogEventFactory=org.logstash.log.LogstashLogEventFactory
		log4j2.messageFactory=org.logstash.log.LogstashMessageFactory

Migrate Logstash to Log4j2 Logging #5651

Migrate Logstash to Log4j2 Logging #5651

Uh oh!

Conversation

talevy commented Jul 19, 2016

Uh oh!

fbaligand commented Jul 19, 2016

Uh oh!

fbaligand Jul 19, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

talevy Jul 20, 2016

Choose a reason for hiding this comment

Uh oh!

suyograo commented Aug 11, 2016

Uh oh!

ph Aug 11, 2016

Choose a reason for hiding this comment

Uh oh!

ph commented Aug 11, 2016

Uh oh!

ph commented Aug 24, 2016

Uh oh!

ph commented Aug 24, 2016

Uh oh!

ph commented Aug 24, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

suyograo commented Aug 24, 2016

Uh oh!

ph commented Aug 24, 2016

Uh oh!

fbaligand Aug 25, 2016

Choose a reason for hiding this comment

Uh oh!

talevy Aug 25, 2016

Choose a reason for hiding this comment

Uh oh!

fbaligand Aug 25, 2016

Choose a reason for hiding this comment

Uh oh!

fbaligand commented Aug 25, 2016

Uh oh!

ph commented Aug 25, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ph commented Aug 25, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

talevy commented Aug 25, 2016

Uh oh!

ph commented Aug 25, 2016

Uh oh!

talevy commented Aug 25, 2016

Uh oh!

Uh oh!

fbaligand Jul 19, 2016 •

edited

Loading

ph commented Aug 24, 2016 •

edited

Loading

ph commented Aug 25, 2016 •

edited

Loading

ph commented Aug 25, 2016 •

edited

Loading