Header warning logging refactoring #55941

pgomulka · 2020-04-29T14:03:09Z

Splitting DeprecationLogger into two. HeaderWarningLogger - responsible for adding a response warning headers and ThrottlingLogger - responsible for limiting the duplicated log entries for the same key (previously deprecateAndMaybeLog).
Introducing A ThrottlingAndHeaderWarningLogger which is a base for other common logging usages where both response warning header and logging throttling was needed.

relates #55699
relates #52369

refactor

elasticmachine · 2020-04-29T14:03:11Z

Pinging @elastic/es-core-infra (:Core/Infra/Logging)

jakelandis · 2020-05-05T02:19:30Z

server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java

+    /**
+     * Logs a message, adding a formatted warning message as a response header on the thread context.
+     */
+    public void headerWarnAndLog(String msg, Object... params) {


can we make this just logAndHeader I think that is different enough from info, warn etc. and you can always look up at the type of logger.

can we also expose a log and a header method ? log = logfile, warn = header

ninja edit - s/warn/header (in case the comments here don't line up with the contents in the email updates)

agree - log and header method will be useful too. Not sure about the header method name though #55941 (comment)

hm at the same time there is no usage for just log/header on its own at the moment.
maybe let's keep that class small for now and add methods as the need arise?

jakelandis · 2020-05-05T02:20:18Z

server/src/main/java/org/elasticsearch/common/logging/HeaderWarningLogger.java

+        }
+    }
+
+    public void log(String msg, Object... params) {


can this be header instead of log ?

hm not sure about this one. Wouldn't some verb be better here? addHeader? addHeaderWarning?
or maybe simply log as it is now. The class name and the field name should express the intent

pgomulka · 2020-05-06T11:02:20Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

-        } else {
-            return ch;
-        }
+    public void deprecatedAndMaybeLog(final String key, final String msg, final Object... params) {


@jakelandis I am also considering renaming these as deprecatedAndMaybe is not clear enough
I think this should be just throttleLogAndWarnOnHeader and logAndWarnOnHeader
the destination -deprecation log - is clear from the name of the field and class

jakelandis · 2020-05-06T15:20:50Z

We discussed this a bit more in person and came to the following conclusions. This refactoring servers two purposes a) expose the ability to emit HTTP warnings back to the client outside of deprecations e.g. #55699 b) provide a means to expose compatibility logging which is very similar to deprecation logging, but slightly different.

a) This PR will pull apart the HTTP warming emitter code and allow users to use it separately from the deprecation logger. Something like httpWarning.addEntry("http warning"); This will not go to the log file. We discussed possibly allowing this also go to the normal server log file, but throttled. However, there are some concerns about throttling messages messages to the main server log file since it could easily get lost and the server log and deprecation log server different purposes. We could at some future point introduce a throttled log message to the server, but will need more consideration then simply re-using what we have for the deprecation logger.

b) Deprecation logs and compatibility logs and highly related. A deprecation message might say [DELETE /_xpack/watcher/watch/{id}] is deprecated! Use [DELETE /_watcher/watch/{id}] instead, and compatibility log may say API request /_xpack/watcher/watch/{id} has been converted to /_watcher/watch/{id}. The deprecation tells you what is deprecated and what to do to fix, and the compatibility tells you what done by using the API compatibility. After some discussion we plan to represent both of these in the deprecation logfile, but with different types. For example:

{"type": "deprecation", x-opaque-id: "asfsdafsadfsdf", timestamp": "2020-05-05T15:43:44,034Z", "level": "INFO", "component": "o.e.d.x.w.r.a.RestDeleteWatchAction", "cluster.name": "monitor-cluster", "node.name": "es_monitor", "message": "[DELETE /_xpack/watcher/watch/{id}] is deprecated! Use [DELETE /_watcher/watch/{id}] instead.", "cluster.uuid": "XAfLzlIbTlqqEr4oT2W5QA", "node.id": "rCdN080aRoy94UcE7IT7KQ"  }
{"type": "compatibility", x-opaque-id: "asfsdafsadfsdf", "timestamp": "2020-05-05T15:43:44,034Z", "level": "INFO", "component": "o.e.d.x.w.r.a.RestDeleteWatchAction", "cluster.name": "monitor-cluster", "node.name": "es_monitor", "message": "API request /_xpack/watcher/watch/{id} has been converted to /_watcher/watch/{id}", "cluster.uuid": "XAfLzlIbTlqqEr4oT2W5QA", "node.id": "rCdN080aRoy94UcE7IT7KQ"  }

This allow for easy separation of the messages (as opposed to smashing the two texts to the same message), and does not occur any additional over head of managing yet another log file. To help developers introduce a compatibility message into the deprecation we plan to introduce a fluent api similar to :

deprecationLogger
	.deprecate("[DELETE /_xpack/watcher/watch/{id}] is deprecated! Use [DELETE /_watcher/watch/{id}] instead")
	.compatibility("API request /_xpack/watcher/watch/{id} has been converted to /_watcher/watch/{id}")
	.log(Logger.INFO)

So when a developer needs to add a compatibility message, it is easy as adding to the existing deprecrationLogger .

note - The above is a proposal and the final outcome may deviate

pgomulka · 2020-05-11T15:28:28Z

server/src/main/java/org/elasticsearch/cluster/metadata/MetadataIndexTemplateService.java

@@ -367,8 +366,7 @@ public ClusterState addIndexTemplateV2(final ClusterState currentState, final bo
                    .map(e -> e.getKey() + " => " + e.getValue())
                    .collect(Collectors.joining(",")),
                name);
-            logger.warn(warning);
-            deprecationLogger.deprecatedAndMaybeLog("index_template_pattern_overlap", warning);
+            warningLogger.logAndAddWarning(warning);


this is the usage of the refactoring from this PR.
this log line always log - to server - and adds a warning.
The type might be a bit confusing. Maybe this should 2 lines:

to log to a server file - regular logger

add a warning to a headers
@jakelandis wdyt?

++ for 2 lines. We should also probably make ThrottlingAndHeaderWarningLogger package private.

jakelandis

Changes are looking good. A couple minor comments.

jakelandis · 2020-05-13T15:47:47Z

qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java

@@ -67,6 +67,7 @@

    @Override
    public void setUp() throws Exception {
+        assert "false".equals(System.getProperty("tests.security.manager")) : "-Dtests.security.manager=false has to be set";


did this slip in, or is it intentional ?

probably not directly related to the refactoring, but it is useful when running this test from intellij to get that reminder. not obvious from just a failure message why the test failed

jakelandis · 2020-05-13T16:07:24Z

server/src/main/java/org/elasticsearch/cluster/metadata/MetadataIndexTemplateService.java

@@ -367,8 +366,7 @@ public ClusterState addIndexTemplateV2(final ClusterState currentState, final bo
                    .map(e -> e.getKey() + " => " + e.getValue())
                    .collect(Collectors.joining(",")),
                name);
-            logger.warn(warning);
-            deprecationLogger.deprecatedAndMaybeLog("index_template_pattern_overlap", warning);
+            warningLogger.logAndAddWarning(warning);


++ for 2 lines. We should also probably make ThrottlingAndHeaderWarningLogger package private.

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java

jakelandis · 2020-05-13T16:18:18Z

server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java

+ * This class wraps both <code>HeaderWarningLogger</code> and <code>ThrottlingLogger</code>
+ * which is a common use case across Elasticsearch
+ */
+public class ThrottlingAndHeaderWarningLogger {


can we make this package private ?

jakelandis · 2020-05-13T16:20:57Z

server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java

+     */
+    //TODO fix this
+    @SuppressLoggerChecks(reason = "safely delegates to logger")
+    public void logAndAddWarning(String msg, Object... params) {


as discussed in person, i think this can be removed since we only want to expose the Deprecation logger and the Header warning logger. We want to avoid general usaage of this class and if a user wants to always header warn they can use that method and throttling to the main server log is something that that requires more consideration.

jakelandis · 2020-05-13T16:21:42Z

server/src/main/java/org/elasticsearch/common/logging/ThrottlingLogger.java

+        }
+    }
+
+    void log(Message message) {


I think with the following comment: https://github.com/elastic/elasticsearch/pull/55941/files#r421840660 we can make this private.

jakelandis · 2020-05-13T16:24:55Z

test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java

-            args = new Object[] { "world", 43, "another argument" };
-        }
-        logger.info(message, args);
+//    public void checkArgumentsProvidedInConstructor() {


don't forget to uncomment :)

pgomulka · 2020-05-14T12:46:56Z

@elasticmachine run elasticsearch-ci/2

pgomulka · 2020-05-14T14:51:03Z

@jakelandis I updated the PR as per comments. Re discussion on test cases - The additional throttling test cases for throttling are in JsonLoggerTests - they all pass now.
I made a note to myself with future refactoring (eliminating the key by caching call site and considering reducing garbage creation within fluent builder) on #49087

jakelandis

LGTM ( a couple optional minor doc comments )

jakelandis · 2020-05-31T20:40:22Z

server/src/main/java/org/elasticsearch/common/logging/HeaderWarning.java

+
+/**
+ * This is a simplistic logger that adds warning messages to HTTP headers.
+ * It uses ThreadContext - which is assumed to be one per JVM (except for tests) - to store warning headers.


This comment (uses ThreadContext ...) is abit confusing. What do I need to do with that knowledge ?

Can you add a usage section to the doc ?

agree, ThreadContext is an implementation detail. I will reword that javadoc

jakelandis · 2020-05-31T20:46:16Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

-            throw new IllegalStateException("Removing unknown ThreadContext not allowed!");
-        }
-    }
+    private final ThrottlingAndHeaderWarningLogger deprecationLogger;


Can you beef up the class level doc a little bit ? Just a quick mention that it does a throttle log (and what it throttling ..or link to the throttling class) and a warning message. Also a small usage in the description would be great.

good idea, added usage and more detailed javadoc.

Splitting DeprecationLogger into two. HeaderWarningLogger - responsible for adding a response warning headers and ThrottlingLogger - responsible for limiting the duplicated log entries for the same key (previously deprecateAndMaybeLog). Introducing A ThrottlingAndHeaderWarningLogger which is a base for other common logging usages where both response warning header and logging throttling was needed. relates elastic#55699 relates elastic#52369

Splitting DeprecationLogger into two. HeaderWarningLogger - responsible for adding a response warning headers and ThrottlingLogger - responsible for limiting the duplicated log entries for the same key (previously deprecateAndMaybeLog). Introducing A ThrottlingAndHeaderWarningLogger which is a base for other common logging usages where both response warning header and logging throttling was needed. relates #55699 relates #52369 backports #55941

pgomulka added 3 commits April 29, 2020 15:59

draft

4d1732e

abstract logger and compatible logger usage

c1d5b13

logging

50a1896

refactor

pgomulka added WIP :Core/Infra/Logging Log management and logging utilities labels Apr 29, 2020

elasticmachine added the Team:Core/Infra Meta label for core/infra team label Apr 29, 2020

pgomulka added 10 commits April 30, 2020 11:34

unnecessary changes

47aca03

delegation instead inhertiance

f6cb937

metadataindex template usage

f7d459a

tests restructure

521c09e

checkxtyle

104a1bc

test fixes and javadoc

913fa42

Merge branch 'master' into logging-refactor

0ee82ae

fix test assert about warning

c17e55f

unused code

afd8d22

reorder methods

3cb8ff9

pgomulka removed the WIP label May 4, 2020

pgomulka changed the title ~~WIP Header warning logging refactoring~~ Header warning logging refactoring May 4, 2020

pgomulka marked this pull request as ready for review May 4, 2020 12:45

pgomulka mentioned this pull request May 4, 2020

WIP Logging compatible API warnings #55608

Closed

jakelandis reviewed May 5, 2020

View reviewed changes

pgomulka commented May 6, 2020

View reviewed changes

clean up refactor

7aa9cdb

pgomulka added 4 commits May 7, 2020 15:07

fluent builder start

d0006b6

use fluent builder

5f55470

rename

039a950

do not throttle to server log

408cc80

pgomulka added 6 commits May 8, 2020 15:34

rename headerwarning

106f528

fix tests

bf219ba

Merge branch 'master' into logging-refactor

6777c92

change to deprecate fluent method

4f68bab

line length

3f6c3a6

inline log method

65a67bc

pgomulka commented May 11, 2020

View reviewed changes

pgomulka added 3 commits May 11, 2020 19:09

arguments fix

7342640

unused import

a37e40b

fix test

d48a323

jakelandis requested changes May 13, 2020

View reviewed changes

pgomulka added 2 commits May 14, 2020 12:37

follow up

11fe609

Merge branch 'master' into logging-refactor

c77405f

Merge branch 'master' into logging-refactor

aa22a54

jakelandis approved these changes May 31, 2020

View reviewed changes

pgomulka added 2 commits June 1, 2020 13:44

javadoc

20125dd

Merge branch 'master' into logging-refactor

dffd16d

pgomulka merged commit 4d6dc51 into elastic:master Jun 1, 2020

pgomulka added the v8.0.0 label Jun 15, 2020

pgomulka mentioned this pull request Jul 22, 2020

Write deprecation logs to a data stream #58924

Closed

pgomulka added the v7.10.0 label Aug 25, 2020

andreidan added the >enhancement label Oct 8, 2020

jakelandis added v8.0.0-alpha1 and removed v8.0.0 labels Jul 26, 2021

jakelandis mentioned this pull request Aug 8, 2024

Add support for a "warning" logger #55699

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Header warning logging refactoring #55941

Header warning logging refactoring #55941

pgomulka commented Apr 29, 2020 •

edited

Loading

elasticmachine commented Apr 29, 2020

jakelandis May 5, 2020 •

edited

Loading

jakelandis May 5, 2020 •

edited

Loading

jakelandis May 5, 2020

pgomulka May 6, 2020

pgomulka May 6, 2020

jakelandis May 5, 2020 •

edited

Loading

pgomulka May 6, 2020

pgomulka May 6, 2020

jakelandis commented May 6, 2020

pgomulka May 11, 2020

jakelandis May 13, 2020

jakelandis left a comment

jakelandis May 13, 2020

pgomulka May 14, 2020

jakelandis May 13, 2020

jakelandis May 13, 2020

jakelandis May 13, 2020

jakelandis May 13, 2020

jakelandis May 13, 2020

pgomulka commented May 14, 2020

pgomulka commented May 14, 2020 •

edited

Loading

jakelandis left a comment

jakelandis May 31, 2020

pgomulka Jun 1, 2020

jakelandis May 31, 2020

pgomulka Jun 1, 2020

Header warning logging refactoring #55941

Header warning logging refactoring #55941

Conversation

pgomulka commented Apr 29, 2020 • edited Loading

elasticmachine commented Apr 29, 2020

jakelandis May 5, 2020 • edited Loading

Choose a reason for hiding this comment

jakelandis May 5, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jakelandis May 5, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jakelandis commented May 6, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jakelandis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pgomulka commented May 14, 2020

pgomulka commented May 14, 2020 • edited Loading

jakelandis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pgomulka commented Apr 29, 2020 •

edited

Loading

jakelandis May 5, 2020 •

edited

Loading

jakelandis May 5, 2020 •

edited

Loading

jakelandis May 5, 2020 •

edited

Loading

pgomulka commented May 14, 2020 •

edited

Loading