Implement log formatter #81

QubitPi · 2016-10-28T15:35:14Z

Issue #74

archolewa · 2016-10-28T16:04:41Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/JsonLogFormatter.java

+ */
+public class JsonLogFormatter implements LogFormatter {
+    private static final Logger LOG = LoggerFactory.getLogger(RequestLog.class);
+    private final ObjectMapper mapper = new ObjectMapper();


This ObjectMapper should be configured with the same modules as the original mapper in RequestLog (which incidentally also needs to be removed).

archolewa · 2016-10-28T16:06:04Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatter.java

+    /**
+     * Takes in a log block and returns a formatted String to be logged.
+     *
+     * @param logBlock the log block that represents a log and that will be formatted in to the needed format.


Should have two spaces between parameter name and description.

archolewa · 2016-10-28T16:06:38Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+ */
+public class LogFormatterProvider {
+
+    private static final Logger LOG = LoggerFactory.getLogger(SystemConfigProvider.class);


Incorrect class (should be LogFormatterProvider.class not SystemConfigProvider.class

archolewa · 2016-10-28T16:10:35Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+
+    private static final Logger LOG = LoggerFactory.getLogger(SystemConfigProvider.class);
+
+    private static final String LOG_FORMATTER_IMPL_KEY = "fili__log_formatter_impl";


This shouldn't be prefixed with fili. We should be getting the module name from the SystemConfig.

(That's what SystemConfig::getPackageVariableName does).

archolewa · 2016-10-28T16:12:00Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+        String logFormatterImplementation = System.getenv(LOG_FORMATTER_IMPL_KEY);
+        try {
+            if (logFormatterImplementation == null) {
+                logFormatterImplementation = System.getProperty(LOG_FORMATTER_IMPL_KEY, DEFAULT_LOG_FORMATTER_IMPL);


I think here you should actually be using an instance of SystemConfig:

logFormatterImplementation = SystemConfigProvider.getInstance().getStringProperty( SYSTEM_CONFIG.getPackageVariableName(LOG_FORMATTER_IMPL_KEY), DEFAULT_LOG_FORMATTER_IMPL );

Also, I think line 35 can be removed, and we can drop the null check.

@michael-mclawhorn Could probably can verify that for me.

The reason the SystemConfigProvider accesses the environment directly, is because it can't very well ask itself about its configuration parameter!

Everything else should go through the SystemConfig object though.

archolewa · 2016-10-28T20:08:27Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+
+    private static final String LOG_FORMATTER_IMPL_KEY = SystemConfigProvider.getInstance().getStringProperty(
+            SYSTEM_CONFIG.getPackageVariableName("log_formatter_impl"),
+            "fili__log_formatter_impl"


The second argument to getStringProperty is not a fully qualified config variable, it's a default setting for the config parameter. In other words, the second argument to getStringProperty should be DEFAULT_LOG_FORMATTER_IMPL not fili__log_formatter_impl.

archolewa · 2016-10-28T20:28:41Z

👍

cdeszaq

Changelog entry needed. Likely under the Added section

cdeszaq · 2016-10-28T21:53:12Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/JsonLogFormatter.java

+ */
+public class JsonLogFormatter implements LogFormatter {
+    private static final Logger LOG = LoggerFactory.getLogger(RequestLog.class);
+    private final ObjectMapper objectMapper = new ObjectMapper();


Not a big deal, but it would be better to just construct this in the constructor, since that's where it's being configured anyways. Colcating the creation and configuration code would be good.

cdeszaq · 2016-10-28T21:54:36Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/JsonLogFormatter.java

+        } catch (JsonProcessingException jsonProcessingException) {
+            String message = String.format("Exporting mega log line: '%s' to JSON failed.", logBlock);
+            LOG.warn(message, jsonProcessingException);
+            return message;


It seems strange that we'd want to log the logBlock as this error message. Perhaps we should just return it's toString value instead of this message?

cdeszaq · 2016-10-28T22:12:54Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+    private static final String DEFAULT_LOG_FORMATTER_IMPL = JsonLogFormatter.class.getCanonicalName();
+
+    private static final String LOG_FORMATTER_IMPL_KEY = SystemConfigProvider.getInstance().getStringProperty(
+            SYSTEM_CONFIG.getPackageVariableName("log_formatter_impl"),


Can we expand this to implementation? In general, we try to avoid abbreviations if we can so that the code is more understandable and clear.

cdeszaq · 2016-10-28T22:18:54Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+        if (LOG_FORMATTER != null) {
+            return LOG_FORMATTER;
+        }
+        String logFormatterImplementation = System.getenv(LOG_FORMATTER_IMPL_KEY);


This construction allows for the LOG_FORMATTER singleton holder to be unset if somehow something calls getInstance before this class does. It shouldn't happen, but it would be good if we can insulate ourselves. A better construction is something like this:

public String getInstance() { if (MY_INSTANCE == null) { // create myInstance MY_INSTANCE = myInstance; } return MY_INSTANCE; }

By having only 1 return path, it's easier to reason about having set the singleton holder.

And if you want to get even more paranoid, you can have the body of that if be it's own synchronized helper method (which should also check if it's already set).

cdeszaq · 2016-10-28T22:21:54Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+            }
+            return (LogFormatter) Class.forName(logFormatterImplementation).newInstance();
+        } catch (Exception e) {
+            LOG.error("Exception while loading Log formatter: {}", e.getMessage(), e);


There's no use in having the exception message as it's own parameter, and in fact it's actively hiding information in this call because you only have 1 placeholder in the log message template. (ie. e will not get logged)

Instead, since SLF4J log calls can natively handle exceptions, just have a call like this: LOG.error("message", e), passing the exception as the only parameter.

cdeszaq · 2016-10-28T22:22:14Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+            return (LogFormatter) Class.forName(logFormatterImplementation).newInstance();
+        } catch (Exception e) {
+            LOG.error("Exception while loading Log formatter: {}", e.getMessage(), e);
+            throw new IllegalStateException(e);


We should make sure to include the message we're logging in the exception as a message as well.

cdeszaq · 2016-10-28T22:25:01Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatter.java

+     *
+     * @return a formatted String to be logged
+     */
+    String write(LogBlock logBlock);


It's strange that this method is called write and not format when the interface is a Formatter. Can we change the name of the method to format? (it's also not supposed to be writing anything, only returning the LogBlock as a formatted string.)

cdeszaq · 2016-10-28T22:25:54Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java

-            LOG.warn(msg, jpe);
-            return msg;
-        }
+        return LogFormatterProvider.getInstance().write(current.info);


Since there's now no longer any requirement that this return JSON, we should update the JavaDoc on this method to reflect that as well.

cdeszaq

Just a couple of small things and this'll be good to go I think!

cdeszaq · 2016-10-31T15:52:42Z

CHANGELOG.md

@@ -10,6 +10,8 @@ Current

 ### Added:

+- [Customize Logging Format](https://github.com/yahoo/fili/pull/81)


This should mention that it's the RequestLog, not all logs in general

cdeszaq · 2016-10-31T15:59:40Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+                return (LogFormatter) Class.forName(logFormatterImplementation).newInstance();
+            } catch (Exception exception) {
+                LOG.error("Exception while loading Log formatter: {}", exception);
+                throw new IllegalStateException(exception.getMessage());


We should always include the causing exception as an exception's Cause when creating a new exception.

michael-mclawhorn · 2016-10-31T16:36:56Z

I'd like to see some tests. Test that the Json log formatter produces something reasonable from a LogBlock at the very least. Test that you get the expected LogFormatter based on configuration would also be nice. (if you implement my suggestion with definalizing the LogFormatter, you could test with one and then with the other by tweaking configuration)

michael-mclawhorn · 2016-10-31T16:33:30Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+     * The instance of the Log Formatter.
+     */
+    private static final LogFormatter LOG_FORMATTER = getInstance();
+


I'm not convinced that final is the correct behavior here. SystemConfig was intended to allow bootstrapping to more sophisticated configurations at runtime. I'm not sure that it wouldn't make sense to allow this to do the same.

There are many cases where we're pulling in config'd things and making them final, so I think this would be the least of the worries in the "updatable runtime config" world. That said, to pull such a config mechanism off, either this would need to be a Supplier<LogFormatter>, or there would need to be a different out-of-band mechanism for updating this field. Either way, having a field be non-runtime-updatable (ie. final) would still be perfectly allowable, if inadvisable) so I don't see any trouble with it (personally.)

archolewa · 2016-10-31T16:38:36Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/LogFormatterProvider.java

+     */
+    public static LogFormatter getInstance() {
+        if (LOG_FORMATTER == null) {
+            String logFormatterImplementation = System.getenv(LOG_FORMATTER_IMPLEMENTATION_KEY);


We shouldn't be going to the environment directly at all. The default implementation of SystemConfig (LayeredSystemConfig) already goes to the environment first, and if a customer introduces their own custom system configuration that changes the priority of the environment (or doesn't want to use it all) they'll get incorrect behavior here.

We should only be going to the SystemConfigProvider.

cdeszaq

👍 after @archolewa's concern about the config value gets addressed

archolewa · 2016-10-31T18:40:23Z

Reafirrming my 👍. Running the tests locally, and then I'll merge it in.

archolewa requested changes Oct 28, 2016

View reviewed changes

cdeszaq added NEED CHANGES NEED 2 REVIEWS REVIEWABLE labels Oct 28, 2016

archolewa added NEED REBASE and removed NEED CHANGES NEED REBASE labels Oct 28, 2016

archolewa requested changes Oct 28, 2016

View reviewed changes

archolewa added NEED 1 REVIEW NEED SQUASH and removed NEED 2 REVIEWS labels Oct 28, 2016

archolewa approved these changes Oct 28, 2016

View reviewed changes

archolewa removed the NEED SQUASH label Oct 28, 2016

cdeszaq requested changes Oct 28, 2016

View reviewed changes

cdeszaq added the NEED CHANGES label Oct 28, 2016

archolewa added NEED SQUASH and removed NEED CHANGES labels Oct 31, 2016

implement log formatter

e2f8e57

cdeszaq requested changes Oct 31, 2016

View reviewed changes

archolewa removed the NEED SQUASH label Oct 31, 2016

michael-mclawhorn requested changes Oct 31, 2016

View reviewed changes

archolewa reviewed Oct 31, 2016

View reviewed changes

address comment

c6aef81

cdeszaq approved these changes Oct 31, 2016

View reviewed changes

cdeszaq added MERGEABLE NEED CHANGES and removed NEED 1 REVIEW REVIEWABLE labels Oct 31, 2016

address comment about config value

d947353

archolewa removed the NEED CHANGES label Oct 31, 2016

archolewa merged commit d5a5ea4 into yahoo:master Oct 31, 2016

QubitPi deleted the implement-logFormatter branch October 31, 2016 18:51

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement log formatter #81

Implement log formatter #81

QubitPi commented Oct 28, 2016 •

edited

Loading

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa Oct 28, 2016

archolewa commented Oct 28, 2016

cdeszaq left a comment

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq Oct 28, 2016

cdeszaq left a comment

cdeszaq Oct 31, 2016

cdeszaq Oct 31, 2016

michael-mclawhorn commented Oct 31, 2016

michael-mclawhorn Oct 31, 2016

cdeszaq Oct 31, 2016

archolewa Oct 31, 2016 •

edited

Loading

cdeszaq left a comment

archolewa commented Oct 31, 2016 •

edited

Loading


		private static final Logger LOG = LoggerFactory.getLogger(SystemConfigProvider.class);

		private static final String LOG_FORMATTER_IMPL_KEY = "fili__log_formatter_impl";

		@@ -10,6 +10,8 @@ Current

		### Added:

		- [Customize Logging Format](https://github.com/yahoo/fili/pull/81)

Implement log formatter #81

Implement log formatter #81

Conversation

QubitPi commented Oct 28, 2016 • 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

archolewa commented Oct 28, 2016

cdeszaq 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

Choose a reason for hiding this comment

cdeszaq left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michael-mclawhorn commented Oct 31, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

archolewa Oct 31, 2016 • edited Loading

Choose a reason for hiding this comment

cdeszaq left a comment

Choose a reason for hiding this comment

archolewa commented Oct 31, 2016 • edited Loading

QubitPi commented Oct 28, 2016 •

edited

Loading

archolewa Oct 31, 2016 •

edited

Loading

archolewa commented Oct 31, 2016 •

edited

Loading