JSON Logging in Quarkus based Keycloak

[DGuhr]

Context & History:

This is a follow-up of the general discussion in #8870
The ootb json logging in Quarkus falls short on configuration capabilities for our use-case, it would result in multiple empty fields, as we don't use e.g. mdc/ndc (see e.g. here for more details: ).

There is a quarkiverse extension here https://github.com/quarkiverse/quarkus-logging-json/ that gives us far more capabilities for a nice json logging user experience, and is also referred to by quarkus core team members. So after careful consideration of "adding another dependency" I'd build a first version that uses this extension. For a first milestone, we'll go with the ootb quarkus json logging support, and try to improve the log output later on.

Scope:

We want to have the following json log capabilities:

Milestone 1:

• enable/disable at runtime (not a build option)

Milestone 2:

• remove unused fields (Quarkus json logging per default adds all fiels, including e.g. mdc/ndc which we are not using now)

(potentially) next Milestones could include:

• switch format from default structured to ecs (?)
• Ability to configure unneeded fields.
• support for structured logging arguments/extending the log provider (the extension has capabilities to do it, so we're not closing gates on this, but not needed for a v1)

Intentionally Out of Scope:

• file log support
• syslog log support
• request logging
• mdc support

Proposal for configuration options (format: <key>=<values>:<default> )

log-json-enabled=true/false:false

Proposal for potential configuration options for further iterations (format: <key>=<values>:<default> )

log-json-format=ecs|default:default

log-json-fields=...,...,...,...,...:default - default is a wrapper for fields: level, logger name, timestamp, message)

log-json-fields-disabled=...,...,...,...,...,...:all but default, see above.

Already Open Questions:

• json enabled per default in production mode: yes or no? PoV so-far: postpone this decision, as the impl is trivial

• How to handle output when invoking "build", "show-config" or similar? Here we have a mix of cli logs outside of quarkus (no log framework yet, so always unstructured) and especially for the build command, where we call quarkus in a somewhat "undefined" middle state between two new "closed world assumptions", because we're re-augmenting it. This leads to non-structured output, as quarkus is not aware of "json is turned on" in this middle state.
  PoV so-far: As it is intended behaviour to run the "build" on another point in time / another step (e.g. in a CI before publishing the img to a registry) I ignored this as "not important" for now, but may be wrong. We're effectively calling QuarkusEntryPoint.Main() here, so when we want to do sth about it we most likely have to create a quarkus issue/PR.

[stianst]

Could you provide some more context on why there's a need for default and ecs formats?

What are the use-cases to be able to include/exclude fields? Is this really needed other than ability to remove the unused fields?

From a community health perspective I'm concerned with the proposed extension as it does not seem to be a actively maintained project, but more a "it fits our need, and we open sourced it".

A quick review of the community health:

• Lack of security policy
• Lack of listed maintainers
• Lack of contributors guide
• A single maintainer from what I can see, which is problematic
• Very few watches/stars
• Fairly inactive project based on recent commits, closed issues, and PRs

A positive is that there are no transitive runtime dependencies other than Quarkus. Also, positive that it is using Maven. Have you tried to clone the repository and build the project? Have you reviewed the source code?

[DGuhr]

On ECS:
The format was asked for here: #8870 and it is a very widely used format. Not hard on making the switch available as an option, though.

On use-cases:
I can see multiple use-cases for including/excluding fields . E.g. while developing extensions, for example "i want to know the sequence of log entries to see if my extension behaves corretly when integrated with keycloak", "I want to see the threadId for my extensions process", ..." but not intentionally interesting for end users. But may be.

Normally desired for someone who checks logs is "have at least clutter as possible", so I wanted to provide very minimal defaults, with the ability to extend them, or even strip them down more.

On community health:
Most points are surely valid, and I agree this is a border case. For me the biggest argument in favor of using the ext. for now is that even the quarkus ppl are pointing to it as go-to-solution, we will most likely not see extended json support ootb (all in the thread i linked) and it won't block us from "moving it in" into our codebase instead in the future when we ever think it's needed, as it does not have transitive dependencies etc.

[softmetz]

I am also very interested in ECS output, as this is what our logging infrastructure expects. Any current developments on this? I looked into Quarkus but there it is not a much requested feature, probably due the existence of the Quarkus Logging JSON extension, which at least in Keycloak 20 is not usable by deploying in the providers directory.

1.1.1 is conflicting with the core quarkus-logging-json extension and 2.0.0 brings up missing dependencies, mostly missing java.io.Map ConfigProperty.

[pedroigor]

How to handle output when invoking "build", "show-config" or similar? Here we have a mix of cli logs outside of quarkus (no log framework yet, so always unstructured) and especially for the build command, where we call quarkus in a somewhat "undefined" middle state between two new "closed world assumptions", because we're re-augmenting it. This leads to non-structured output, as quarkus is not aware of "json is turned on" in this middle state.

I can not think about any argument that justifies logging when running build or show-config. IMO, that is definitely a runtime thing and targeted for monitoring and collecting data when at runtime.

I'm also not 100% sure if including/excluding fields is so important. At least in a v1. it is also not clear the effort to extend the core extension to provide this capability and others that we might need.

[DGuhr]

Updated the discussion to have a very basic v1 using the ootb quarkus json logging capabilities.

[DGuhr]

Initial json console logging support is now in latest main, see #10576 - expect some more options when we get to #10618 - we need quarkus 2.8.0 to be released though.

[AndreiMihaiRad]

I imported quarkiverse extension jar into providers folder (Keycloak 17.0.0).
Also I've created a quarkus.properties file with quarkus.log.console.json.log-format=ecs in there and I put the file into conf/ folder.
Build & Started the app in production mode but logs are still not in json format. Is something that I'm missing ?

Any help would be appreciated.

[pedroigor]

Looks like we need a specific property to configure json format and wrap quarkus.log.console.json.log-format)?

[AndreiMihaiRad]

thanks for response, looking forward for the next release. Do you know a rough estimation when will be the next release date / period ?

[pedroigor]

@DGuhr Shall we have this one targeted for 19? Or do you want to include in 18?

[DGuhr]

@pedroigor i guess more changes to json logging than the ones currently in main will not make it to 18, as quarkus 2.8 is not out and not sure we want to update before 18. more enhancements should be done as part of #10618 and targeted for 19, i'd say.

[DGuhr]

@AndreiMihaiRad Next release will bring general json logging support. Not ECS compliant json logging. The PR for quarkus I mentioned earlier is targeted for quarkus 2.8, which is not released yet. So will most likely not make it into Keycloak 18, but a future version instead.

When Quarkus 2.8 is out, integrated into keycloak, and we made the adjustments to the logging code, json logging will bring the capabilities to:

1. override the json key names (e.g. @timestamp instead of timestamp for ecs compliance)
2. remove unused keys (e.g. we'll most likely remove mdc/ndc fields completely by default, as it is not used at all)
3. add own keys with static value (not 100% we'll add this also to keycloak, but could e.g. be used for service.name in ecs)

so this allows to send ecs formatted logs when i understood the standard right.

[trixpan]

@DGuhr my 2 cents about the current state of keycloak 18.x logging compared to jboss keycloak logging:

• JSON logging seems to only be available on console (via KC_LOG_CONSOLE_OUTPUT). Regression from the previous functionality.

• It seems only one file handler can be created (via KC_LOG) . Ideally we should be able to configure more than one file. This is particularly important in multi-pipeline environments where a team may want to collect operational logs in one ES/Splunk index and send security relevant logs to another ES/Splunk index. While filtering and routing at pipeline level tends to be seen as a great idea it is not always feasible, reason why nearly every log ingestion tool support multiple inputs.

In the past both features were easily achievable with JBoss CLI like:

# First we ensure cute log in console
/subsystem=logging/console-handler=CONSOLE:write-attribute(name=named-formatter, value=PATTERN)

# create a logger we will use to log the events into console. (Somehow if we use add-handler to the events entries,
# normal CONSOLE handler will not longer include the required entries).
/subsystem=logging/console-handler=CUSTOM-CONSOLE:add(named-formatter=PATTERN, autoflush=true, target="System.out")

# Then create a JSON handler and configure the base log file to use it.
/subsystem=logging/json-formatter=json:add(exception-output-type=formatted, pretty-print=false)
/subsystem=logging/periodic-rotating-file-handler=FILE:write-attribute(name=named-formatter, value=json)

# Create a separate stream to ship to SOC. File is also in JSON format
/subsystem=logging/periodic-rotating-file-handler=SECURITY_RELEVANT_EVENTS:add(file={ "relative-to"=>"jboss.server.log.dir","path"=>"security.log"}, suffix=".yyyy-MM-dd", append="true", autoflush="true")
/subsystem=logging/periodic-rotating-file-handler=SECURITY_RELEVANT_EVENTS:write-attribute(name=named-formatter, value=json)

# Then we add a second log file to store plain text log outputs.
# NOTE: This log is for local use only. Do not send theses logs to Splunk.
#       JSON logs are already sent to the Splunk pipeline and are easier to consume in Splunk than plain files.
/subsystem=logging/periodic-rotating-file-handler=PLAIN_FILE:add(file={ "relative-to"=>"jboss.server.log.dir","path"=>"plain_server.log"}, suffix=".yyyy-MM-dd", append="true", autoflush="true")
/subsystem=logging/periodic-rotating-file-handler=PLAIN_FILE:write-attribute(name=named-formatter, value=PATTERN)

# Enable the formatter as a root-logger
/subsystem=logging/root-logger=ROOT:add-handler(name="PLAIN_FILE")

# increase our.custom.provider.events logging level
/subsystem=logging/logger=our.custom.provider.events:add(level=TRACE, use-parent-handlers=false, handlers=["CUSTOM-CONSOLE","PLAIN_FILE", "SECURITY_RELEVANT_EVENTS", "FILE"])

# also configure the native keycloak event tracing logging to all relevant outputs
/subsystem=logging/logger=org.keycloak.events:add(level=DEBUG, use-parent-handlers=false, handlers=["CUSTOM-CONSOLE","PLAIN_FILE", "SECURITY_RELEVANT_EVENTS", "FILE"])

The above can be achieved in Quarkus (and via Keycloak's conf/quarkus.properties) with syntax like

...
quarkus.log.handler.file."SECURITY_RELEVANT_EVENTS".enable=true
# Does not work. Need to fill bug with Quarkus
# quarkus.log.handler.file."SECURITY_RELEVANT_EVENTS".json=true
quarkus.log.handler.file."SECURITY_RELEVANT_EVENTS".path=/opt/jboss/keycloak/standalone/log/security.log
quarkus.log.handler.file."PLAIN_FILE".enable=true
# Does not work. Need to fill bug with Quarkus
# quarkus.log.handler.file."PLAIN_FILE".json=false
quarkus.log.handler.file."PLAIN_FILE".path=/opt/jboss/keycloak/standalone/log/plain_server.log
quarkus.log.category."org.keycloak.events".level=DEBUG
quarkus.log.category."org.keycloak.events".handlers=SECURITY_RELEVANT_EVENTS,PLAIN_FILE
...

Having started coding on data pipeline projects, I suspect I may be on the opposite spectrum of the customer and development bases but feels to me that trying to "solve" logging issues will inevitably lead to spending development resources on a feature that may end up being unable to solve the desirable permutations (simply because data pipelines are a pain on their own and each place handles things very differently from what one would expect is the best way of handling).

I would posit that

• shipping with a sane default and exposing (the already limited) Quarkus logging as purely as possible will result on a better user experience, and
• instead working on a particular solution, advocate with the quarkus community a way of using the JSON processor when sending to non-console handlers.

[trixpan]

BTW, the lack of file capable JSON handlers seem to be an ongoing feature request in Quarkus

quarkusio/quarkus#9386

[yasammez]

The linked issue has been closed. Can we expect a --log-file-output=json config option in the future?

[codespearhead]

@yasammez It's now available via --log-console-output=json.

[DGuhr]

Well, it's 1.5 years later 😇