Skip to content
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

Fix prefix logging #20429

Merged
merged 4 commits into from
Sep 13, 2016
Merged

Fix prefix logging #20429

merged 4 commits into from
Sep 13, 2016

Conversation

jasontedor
Copy link
Member

Today we add a prefix when logging within Elasticsearch. This prefix
contains the node name, and index and shard-level components if
appropriate.

Due to some implementation details with Log4j 2 , this does not work for
integration tests; instead what we see is the node name for the last
node to startup. The implementation detail here is that Log4j 2 there is
only one logger for a name, message factory pair, and the key derived
from the message factory is the class name of the message factory. So,
when the last node starts up and starts setting prefixes on its message
factories, it will impact the loggers for the other nodes.

Additionally, the prefixes are lost when logging an exception. This is
due to another implementation detail in Log4j 2. Namely, since we log
exceptions using a parameterized message, Log4j 2 decides that that
means that we do not want to use the message factory that we have
provided (the prefix message factory) and so logs the exception without
the prefix.

This commit fixes both of these issues.

Today we add a prefix when logging within Elasticsearch. This prefix
contains the node name, and index and shard-level components if
appropriate.

Due to some implementation details with Log4j 2 , this does not work for
integration tests; instead what we see is the node name for the last
node to startup. The implementation detail here is that Log4j 2 there is
only one logger for a name, message factory pair, and the key derived
from the message factory is the class name of the message factory. So,
when the last node starts up and starts setting prefixes on its message
factories, it will impact the loggers for the other nodes.

Additionally, the prefixes are lost when logging an exception. This is
due to another implementation detail in Log4j 2. Namely, since we log
exceptions using a parameterized message, Log4j 2 decides that that
means that we do not want to use the message factory that we have
provided (the prefix message factory) and so logs the exception without
the prefix.

This commit fixes both of these issues.
super(logger, name, null);
this.prefix = prefix;

final String actualPrefix = (prefix == null ? "[] " : prefix).intern();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is a deviation from the 2.x version where a null prefix will be completely dropped. Are you sure this is a good change?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Log4j will not allow a null marker, but I can replace this with the empty string if you prefer.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it will be cleaner? not a biggy though

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I pushed 7c16c6c.

@bleskes
Copy link
Contributor

bleskes commented Sep 12, 2016

I'm not an expert here, but the approach looks like the best we had so far. Left some minor comments.

@bleskes bleskes closed this Sep 12, 2016
@bleskes bleskes reopened this Sep 12, 2016
When a logging prefix is null (e.g., when we do not yet know the node
name), this commit causes such loggers to use an empty string marker
instead of an empty prefix (i.e., "[] ") marker.
This commit fixes some failing logging tests. These tests are failing
due to the changes of the logging prefix. Now that the logging prefix is
used as a marker, we have to adjust the appender and mock appender
conditions to account for the fact that the prefix is no longer part of
the message.
This commit clarifies the intent of PrefixLogger by adding some
comments, and addresses an issue in the de-referencing of a weak
reference.
@bleskes
Copy link
Contributor

bleskes commented Sep 13, 2016

LGTM. Thanks @jasontedor . Another fun adventure.

@jasontedor
Copy link
Member Author

Thank you @bleskes and @mikemccand for careful reviews.

@jasontedor jasontedor merged commit fbe2766 into elastic:master Sep 13, 2016
@jasontedor jasontedor deleted the logging-prefix-by-wrapping branch September 13, 2016 18:46
jasontedor added a commit that referenced this pull request Sep 13, 2016
Today we add a prefix when logging within Elasticsearch. This prefix
contains the node name, and index and shard-level components if
appropriate.

Due to some implementation details with Log4j 2 , this does not work for
integration tests; instead what we see is the node name for the last
node to startup. The implementation detail here is that Log4j 2 there is
only one logger for a name, message factory pair, and the key derived
from the message factory is the class name of the message factory. So,
when the last node starts up and starts setting prefixes on its message
factories, it will impact the loggers for the other nodes.

Additionally, the prefixes are lost when logging an exception. This is
due to another implementation detail in Log4j 2. Namely, since we log
exceptions using a parameterized message, Log4j 2 decides that that
means that we do not want to use the message factory that we have
provided (the prefix message factory) and so logs the exception without
the prefix.

This commit fixes both of these issues.

Relates #20429
jasontedor added a commit that referenced this pull request Sep 13, 2016
Today we add a prefix when logging within Elasticsearch. This prefix
contains the node name, and index and shard-level components if
appropriate.

Due to some implementation details with Log4j 2 , this does not work for
integration tests; instead what we see is the node name for the last
node to startup. The implementation detail here is that Log4j 2 there is
only one logger for a name, message factory pair, and the key derived
from the message factory is the class name of the message factory. So,
when the last node starts up and starts setting prefixes on its message
factories, it will impact the loggers for the other nodes.

Additionally, the prefixes are lost when logging an exception. This is
due to another implementation detail in Log4j 2. Namely, since we log
exceptions using a parameterized message, Log4j 2 decides that that
means that we do not want to use the message factory that we have
provided (the prefix message factory) and so logs the exception without
the prefix.

This commit fixes both of these issues.

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

Successfully merging this pull request may close these issues.

None yet

3 participants