Skip to content

Add Graylog Extended Log Format (GELF) for structured logging #1

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from

Conversation

slissner
Copy link
Owner

@slissner slissner commented Aug 28, 2024

Summary

As of Spring Boot v3.4, structured logging is now built-in into Spring Boot.

The following pull requests adds a Graylog Extended Log Format (GELF) formatter to the structured logging of Spring Boot.

Please review @phxql CC @philwebb

TODO

  • Fix WARN : org.graylog2.inputs.codecs.GelfCodec - GELF message <6164add0-6ace-11ef-81af-0242ac150004> (received from <192.168.65.1:30756>) has invalid "timestamp": 1725462010.152 (type: STRING)
  • We'll need some values in additional-metadata.json so that IDE auto-completion works. There should be some for ElasticCommonSchemaService which can serve as inspiration.
  • Improve GELF Logging Documentation
  • Add a GELF StructuredLogFormatter for the log4j2 integration

To be discussed with the feature authors of Structured Logging

  • It should be better documented that you need to import the structured-console-appender.xml in logback.xml instead of console-appender.xml
  • I am receiving a LogbackException (Log Output) when I start my example logger application. The reason for this is that upon the very first log message, no Spring Environment seems to be. This violates the precondition at org.springframework.boot.logging.logback.StructuredLogEncoder.createFormatter(StructuredLogEncoder.java:71) (Assert.state(environment != null, "Unable to find Spring Environment in logger context");
  • Problem: Some additional fields get swallowed when sending them to Graylog (see below)

Some additional fields get swallowed when sending them to Graylog

In my example logger application, I am using the GELF Appender from https://github.com/osiegmar/logback-gelf from @osiegmar in order to send logs to Graylog.

My new GELF Formatter writes the following log output to my application console:

{
  "version": "1.1",
  "host": "spring-boot-gelf",
  "short_message": "Starting SpringBootGelfApplication using Java 17.0.12 with PID 11263 (/Users/samuel/Documents/slissner/spring-boot-gelf/build/classes/java/main started by samuel in /Users/samuel/Documents/slissner/spring-boot-gelf)",
  "timestamp": "2024-08-28T09:32:49.960196Z",
  "level": "INFO",
  "_process_pid": 11263,
  "_process_thread_name": "main",
  "_service_name": "spring-boot-gelf",
  "_log_logger": "com.slissner.springbootgelf.SpringBootGelfApplication"
}

However, this is the message I have extracted from Graylog:

{
  "gl2_accounted_message_size": 273,
  "gl2_receive_timestamp": "2024-08-28 09:32:50.520",
  "level": 6,
  "testkey_testmessage": "test",
  "gl2_remote_ip": "192.168.65.1",
  "gl2_remote_port": 60521,
  "streams": [
    "000000000000000000000001"
  ],
  "gl2_message_id": "01J6C599YP000003V2JHVX8FMH",
  "source": "samuel-macbook.local",
  "message": "Hello structured logging!",
  "gl2_source_input": "66cc6f57ece8d22a46b859da",
  "userId": 1,
  "gl2_processing_timestamp": "2024-08-28 09:32:50.525",
  "full_message": "Hello structured logging!",
  "thread_name": "main",
  "gl2_source_node": "342c3e9e-9406-4b69-aa50-2b55d8287d08",
  "_id": "7e5e68d0-6520-11ef-b4f6-0242ac150003",
  "logger_name": "com.slissner.springbootgelf.ExampleLogger",
  "gl2_processing_duration_ms": 5,
  "timestamp": "2024-08-28T09:32:50.518Z"
}

Note for example

  • that the _service_name is present in the original console log statement, but not in the graylog message;
  • the fields userId and testkey_testmessage are present because they were added to the MDC at the caller site;
  • the additional fields added as json members are not present (cf. source code of the formatter)

This is because Oliver's library uses its own GelfEncoder for logback. And this encoder encodes the ILoggingEvent instances. It does not simply pass on the JSON my new GELF Formatter generated in Structured Logging.

According to Oliver's implementation, only the fields from the MDC are passed on as additional fields. Fields such as those in GraylogExtendedLogFormatStructuredLogFormatter are NOT passed on.

There are several ways of dealing with this:

  • Simply ignore these problems: One could argue that this is a problem of using a third party library of Oliver and not of Spring Boot; as Spring Structured Logging's responsibility is to print structured logs - nothing else! How logs are appended to Logback (and with which appender) may be deemed not the business of Spring. Please advice!
  • Workaround: Move all additional fields from json members to the MDC in GraylogExtendedLogFormatStructuredLogFormatter.
  • Rethink the design of Structured Logging in Spring Boot regarding Logback Appenders?

Screenshots

Spring Boot GELF Log Output:

Log Output

Graylog:

Graylog

See also

@slissner slissner self-assigned this Aug 28, 2024
@philwebb
Copy link

Hi @slissner,

This looks great! Thanks for taking it on.

Exception

I am receiving a LogbackException

This is because we can't hook into logback correctly with a logback.xml file, rename it to logback-spring.xml and I think it will work.

Other Notes

  • I wonder if the host value should move from GraylogExtendedLogFormatStructuredLogFormatter to GraylogExtendedLogFormatService? It feels like something the user might want to configure.

  • We'll need some values in additional-metadata.json so that IDE auto-completion works. There should be some for ElasticCommonSchemaService which can serve as inspiration.

Sending to Graylog

So far we've designed structured logging to assume that writing to the console or a file is enough to get the structured data to the backend.

There are several ways of dealing with this:

Simply ignore these problems: One could argue that this is a problem of using a third party library of Oliver and not of Spring Boot; as Spring Structured Logging's responsibility is to print structured logs - nothing else! How logs are appended to Logback (and with which appender) may be deemed not the business of Spring. Please advice!

I wonder if we can ask for an update to logback-gelf so that we can plug-in our own StructuredLogEncoder? If GelfHttpAppender accepted a ch.qos.logback.core.encoder.Encoder here I think things would be OK.

Workaround: Move all additional fields from json members to the MDC in GraylogExtendedLogFormatStructuredLogFormatter.

We might be able to get it to work this way, but if feels a bit brittle. We'd be relying on a side-effect of the formatter.

Rethink the design of Structured Logging in Spring Boot regarding Logback Appenders?

I'm not sure how we could change the design and also make things work well with Log4j2. We should probably investigate Log4j2 options for Graylog.

@osiegmar
Copy link

Adding support for GELF output to Spring's structured logging is a nice improvement.

You may want to give https://github.com/osiegmar/logback-gelf/tree/external-encoder a try. I widened the encoder fields of AbstractGelfAppender (used for UDP and TCP) and GelfHttpAppender to Encoder<ILoggingEvent> – that should allow you to use it with Spring's structured logging.

A few hints regarding this PR and your log example:

  • timestamp is not a string, but a number (with only millisecond precision). In logback-gelf, I use new BigDecimal(event.getTimeStamp()).movePointLeft(3).toPlainString() for conversion.
  • level is also a number. In logback-gelf, I use ch.qos.logback.classic.util.LevelToSyslogSeverity.convert for conversion.

@slissner
Copy link
Owner Author

slissner commented Sep 4, 2024

Hi @philwebb and @osiegmar,

Thank you very much for your valuable feedback!

I could resolve almost all the issues we mentioned.

Changes (2024-09-04)

Today I worked on the following:

spring-boot changes

  • Fixed level data type for the serialized GELF message by using LevelToSyslogSeverity::convert.
  • Fixed timestamp formatting with milliseconds precesion (e.g. "1725459730385" -> "1725459730.385")
  • Add _level_name as property to structured log format (e.g. "_level_name: ": "INFO")
  • Log full_message in case there is a throwable present in the log event
  • Move host value to GraylogExtendedLogFormatService

spring-boot-gelf example project changes

  • Fixed the initial LogbackException by moving logback.xml
    to logback-spring.xml
  • In the example application spring-boot-gelf I could successfully use the logback-gelf library in version 6.1.0-SNAPSHOT based on branch external-encoder. I checked out that branched, removed the signing plugin, built the code and published the artifact to my local maven repository. The external encoder works now with StructuredLoggingEncoder! setEncoder
  • Log an example ERROR log with stacktrace attached

TODO

I aim to finalize the following TODOs by tomorrow:

  • Fix WARN : org.graylog2.inputs.codecs.GelfCodec - GELF message <6164add0-6ace-11ef-81af-0242ac150004> (received from <192.168.65.1:30756>) has invalid "timestamp": 1725462010.152 (type: STRING)
  • We'll need some values in additional-metadata.json so that IDE auto-completion works. There should be some for ElasticCommonSchemaService which can serve as inspiration.
  • Improve GELF Logging Documentation
  • Add a GELF StructuredLogFormatter for the log4j2 integration

Screenshots

Some impressions from Graylog.

Overview:

Overview

Info Message:

INFO Message

Error Message:

ERROR Message

@osiegmar
Copy link

osiegmar commented Sep 5, 2024

Sounds good! I've just released logback-gelf version 6.1.0 which is identical to the branch you've tried.

@slissner
Copy link
Owner Author

slissner commented Sep 5, 2024

GELF for Spring Structured Logging (2024-09-05)

After todays work, I reckon that this PR is ready for review.

spring-boot-gelf example project

  • Added branch main-log4j2 which contains an Log4j2 example application (as opposed to the main branch where Logback is used). This example application has no appender set up. It won't send logs to Graylog!

spring-boot changes

  • Resolved: Fix WARN : org.graylog2.inputs.codecs.GelfCodec - GELF message <6164add0-6ace-11ef-81af-0242ac150004> (received from <192.168.65.1:30756>) has invalid "timestamp": 1725462010.152 (type: STRING)
  • Resolved: We'll need some values in additional-metadata.json so that IDE auto-completion works.
  • Add GELF to logging.adoc
  • Add gelf structured log formatter for Log4j2

@slissner slissner marked this pull request as ready for review September 5, 2024 14:26
@slissner slissner changed the title Add Graylog Extended Log Format (GELF) for structured logging WIP Add Graylog Extended Log Format (GELF) for structured logging Sep 5, 2024
- Add `gelf` structured logging formatter with Logback
- Add `gelf` structured logging formatter with Log4j2
- Describe GELF Formatter in the logging documentation
- Add `logging.structured.gelf.service.*` properties to `additional-spring-configuration-metadata.json`
@slissner slissner force-pushed the feature/structured-logging-graylog-gelf branch from 1c91275 to 4452595 Compare September 5, 2024 15:15
@slissner
Copy link
Owner Author

slissner commented Sep 5, 2024

I have now opened an official pull request against the Spring Boot repository: spring-projects#42158

I am closing this PR now. Thanks again for your contributions!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants