Logging to STDOUT in JSON format for containers #15392

bdunne · 2017-06-16T21:57:02Z

Add a StdoutLogger and ContainerFormatter for use in container environment
Add a multicast logger allowing a caller to write to a single "logger" interface and have the message forwarded to multiple backing loggers
$log remains the interface to the callers, but it can now be backed by a MulticastLogger in the container environment which will write to both evm.log in the old format and the StdoutLogger in the format that will be parsed by fluentd and sent to elasticsearch.

carbonin · 2017-06-19T13:38:07Z

lib/vmdb/loggers/formatters/container.rb

@@ -0,0 +1,47 @@
+class ContainerFormatter < Logger::Formatter


Should this be something like FluentFormatter instead? Is this format constant across all container logging aggregators?

Yeah, naming is hard. I don't think this format is specific to fluent though...

carbonin · 2017-06-19T13:40:14Z

This looks really good. A few questions though.

Should we add the messages that are going to other log files to stdout as well? How would we do this without also sending those messages to evm.log?
It seems like this has some duplicated code from the base VMDBLogger. Should we wait for Extract vmdb-logger code from manageiq-gems-pending and insert it into manageiq #15358 and refactor some of that (create our existing formatter and such) as a first step?

gtanzillo · 2017-06-19T13:55:12Z

This is really cool!

imtayadeway · 2017-06-19T15:50:13Z

spec/lib/vmdb/loggers/multicast_logger_spec.rb

+    file2 = StringIO.new
+    multi_logger = described_class.new(Logger.new(file1), Logger.new(file2))
+
+    expect(file1).to receive(:write) do |string|


Did you consider expect(file1.string).to match(/etc../) here?

NickLaMuro · 2017-06-19T16:17:34Z

@carbonin Few things around #15358 and such (since it got mentioned):

Extract vmdb-logger code from manageiq-gems-pending and insert it into manageiq #15358 is probably going to die (see Extract vmdb-logger code from manageiq-gems-pending and insert it into manageiq #15358 (comment) )
Allow lib/vmdb/logging.rb to be required without needing Rails autoloading #15376 will probably conflict with some of the changes here, just a warning

NickLaMuro · 2017-06-19T16:38:45Z

lib/vmdb/loggers.rb

+      $log =
+        if ENV["CONTAINER"]
+          stdout_log = StdoutLogger.new.tap { |l| l.formatter = ContainerFormatter.new }
+          MulticastLogger.new($evm_log, stdout_log)


This is more question than request for change: Is the logging output that is more visible to the user when in a container environment the evm.log file or STDOUT (this is without a common logging interface to view the logs)?

The reason I ask is because in my humble opinion, viewing json formatted logs directly is not user readable, and requires something like kibana to view and digest them sensibly. Obviously json formatted logs makes it machine readable without introducing a parser, but makes the human parseability much less so.

So my follow up to that is do we see users, when the common logging stack is unavailable, using the stdout log or the evm.log to monitor the logs within a container/pod? My request would be to format the more user facing one (which might be what you already have here) with the traditional log formatter, and the one to be parsed by fluentd/logstash be formatted in json.

When looking at the container in Openshift, there is a tab for logs (container STDOUT) where this JSON output woud be visible. There is a separate tab for the Terminal.

jrafanie · 2017-06-19T17:34:34Z

lib/vmdb/loggers/formatters/container.rb

+  private
+
+  def build_message(msg)
+    msg = msg2str(msg)


msg2str 👍

Fryguy · 2017-06-19T18:53:58Z

lib/vmdb/loggers/formatters/container.rb

+    if $_miq_worker_current_msg && !$_miq_worker_current_msg.task_id.nil?
+      prefix = "Q-task_id([#{$_miq_worker_current_msg.task_id}])"
+      msg = "#{prefix} #{msg}" unless msg.include?(prefix)
+    end


Can we piggyback on the existing formatter to do this for us? Or perhaps change the VmdbLogger::Formatter to piggyback on this? I don't really like that this has to be duplicated.

Fryguy · 2017-06-19T18:55:43Z

Does this do the changes as we discussed on the white board? That is, having a single $stdout_logger always on debug, and then the other loggers are more like TeeLoggers (and not writing to N loggers).

miq-bot · 2017-06-19T21:41:50Z

This pull request is not mergeable. Please rebase and repush.

bdunne · 2017-06-20T03:41:49Z

@Fryguy It's now updated with the changes discussed. I think the Formatter name still needs work, but I don't have any ideas.

Fryguy · 2017-06-20T16:46:49Z

lib/vmdb/loggers/multicast_logger.rb

+
+  def initialize(*loggers)
+    require 'set'
+    @loggers = Set.new


You can just do Set.new(loggers), and you don't need to loop over them.

On that note, since you aren't doing any set notation, nor lookups, it's much more efficient to just use a normal Array.

My concern is that you wouldn't want the same logger added more than once to avoid getting duplicate messages.

jrafanie · 2017-06-22T17:59:59Z

lib/vmdb/loggers/multicast_logger.rb

+
+  [:log_backtrace, :log_hashes].each do |method|
+    define_method(method) do |*args|
+      loggers.map { |l| l.send(method, *args) }.first


Note, this implies all loggers passed in through .new have a log_backtrace and log_hashes method which only our loggers have. I wonder if we should check if the provided logger implement those methods and only forward the call to them if they implement it. Maybe that's too much work? Maybe only support our loggers? Or just don't care...

I don't think we care right now. We only have one place using it and it is always backed by one of our loggers.

Fryguy · 2017-06-23T20:53:57Z

lib/vmdb/loggers.rb

-      $websocket_log     = VMDBLogger.new(path_dir.join("websocket.log"))
-      $miq_ae_logger     = VMDBLogger.new(path_dir.join("automation.log"))
+      $container_log     = ContainerLogger.new
+      $log               = MulticastLogger.new(VMDBLogger.new(path_dir.join("evm.log"))).tap           { |l| l.loggers << $container_log if ENV["CONTAINER"] }


Minor, but I feel this should be DRYed up into a method.

Fryguy · 2017-06-23T20:54:37Z

lib/vmdb/loggers/container_logger.rb

+          :level      => translate_error(severity),
+          :message    => prefix_task_id(msg2str(msg)),
+          :pid        => $PROCESS_ID,
+          :tid        => Thread.current.object_id,


.to_s(16) ?

Sounds like I should make it a method on VMDBLogger::Formatter, although I have no idea how it is already .to_s(16) there...

the format (aka %) call in the old logger converted the thread to a string using "%x"

Fryguy · 2017-06-23T20:55:09Z

lib/vmdb/loggers/container_logger.rb

+          :@timestamp => format_datetime(time),
+          :hostname   => hostname,
+          :level      => translate_error(severity),
+          :message    => prefix_task_id(msg2str(msg)),


Doesn't this need a PR to gems pending?

ManageIQ/manageiq-gems-pending#213

Fryguy · 2017-06-23T20:56:07Z

lib/vmdb/loggers/container_logger.rb

+      }.freeze
+
+      def call(severity, time, progname, msg)
+        # From https://github.com/ViaQ/elasticsearch-templates/releases Downloads asciidoc


I tried to follow this URL, but I can't find what you are trying to point to here. What is the Downloads asciidoc?

Follow the link, under "Downloads" you'll see an asciidoc which contains the "schema"

ahh...that wasn't clear to me, as it was a full java-namespace looking thing

Fryguy · 2017-06-23T22:00:57Z

@bdunne Can you please add the $container_log to the rubocop yml. While you're at it, can you DRY this up, so it doesn't go from A to F? 😉

- Allow a caller to write to a single "logger" interface and have the message forwarded to multiple backing loggers

For example: $log remains the interface to the callers, but it can now be backed by a MulticastLogger and in the container environment it will write to both evm.log in the old format and the ContainerLogger (STDOUT) in the format that will be parsed by fluentd and sent to elasticsearch. The AuditLogger already writes to $log which will forward the message

miq-bot · 2017-06-24T09:32:58Z

Checked commits bdunne/manageiq@97ff263~...5f76088 with ruby 2.2.6, rubocop 0.47.1, and haml-lint 0.20.0
5 files checked, 1 offense detected

spec/lib/vmdb/loggers/container_logger_spec.rb

❗ - Line 3, Col 17 - Rails/TimeZone - Do not use Time.now without zone. Use one of Time.zone.now, Time.current, Time.now.in_time_zone, Time.now.utc, Time.now.getlocal, Time.now.iso8601, Time.now.jisx0301, Time.now.rfc3339, Time.now.to_i, Time.now.to_f instead.

carbonin

👍

With the collision of ManageIQ#15058 and ManageIQ#15392 these specs are now failing. Since there's no way to sensibly implement `#reopen` on a multicast logger opaquely, instead we'll add a logger to the multicast loggers and verify against that.

bdunne added core enhancement fine/no labels Jun 16, 2017

bdunne requested review from jrafanie, Fryguy, gtanzillo and carbonin June 16, 2017 21:57

bdunne force-pushed the stdout_logger branch from 1cd59ca to 7edce94 Compare June 16, 2017 22:40

carbonin reviewed Jun 19, 2017

View reviewed changes

imtayadeway reviewed Jun 19, 2017

View reviewed changes

NickLaMuro reviewed Jun 19, 2017

View reviewed changes

jrafanie reviewed Jun 19, 2017

View reviewed changes

Fryguy reviewed Jun 19, 2017

View reviewed changes

bdunne changed the title ~~Logging to STDOUT in JSON format for containers~~ [WIP] Logging to STDOUT in JSON format for containers Jun 19, 2017

miq-bot added the wip label Jun 19, 2017

miq-bot added the unmergeable label Jun 19, 2017

bdunne force-pushed the stdout_logger branch from 7edce94 to a0ce9c3 Compare June 20, 2017 03:36

miq-bot removed the unmergeable label Jun 20, 2017

bdunne changed the title ~~[WIP] Logging to STDOUT in JSON format for containers~~ Logging to STDOUT in JSON format for containers Jun 20, 2017

bdunne removed the wip label Jun 20, 2017

bdunne force-pushed the stdout_logger branch 3 times, most recently from d7ab538 to e2c3305 Compare June 20, 2017 15:53

Fryguy reviewed Jun 20, 2017

View reviewed changes

chessbyte assigned Fryguy Jun 20, 2017

bdunne force-pushed the stdout_logger branch 3 times, most recently from 49f62d9 to 86a70fc Compare June 22, 2017 14:46

jrafanie reviewed Jun 22, 2017

View reviewed changes

bdunne force-pushed the stdout_logger branch from 86a70fc to 4b2bd79 Compare June 23, 2017 13:35

Fryguy reviewed Jun 23, 2017

View reviewed changes

bdunne force-pushed the stdout_logger branch 2 times, most recently from 88152aa to 15f5160 Compare June 23, 2017 22:24

bdunne added 6 commits June 24, 2017 05:27

Add a ContainerLogger and Formatter for use in container environment

97ff263

Add a multicast logger

917a426

- Allow a caller to write to a single "logger" interface and have the message forwarded to multiple backing loggers

Add $container_log to rubocop.yml

3a968f7

move thread_id into a method, to_s(16) for consistency

778fc12

Add a method to reduce duplication of the conditional

5f76088

bdunne force-pushed the stdout_logger branch from 15f5160 to 5f76088 Compare June 24, 2017 09:28

carbonin approved these changes Jun 26, 2017

View reviewed changes

Fryguy merged commit c21568d into ManageIQ:master Jun 26, 2017

Fryguy added this to the Sprint 64 Ending Jul 3, 2017 milestone Jun 26, 2017

bdunne deleted the stdout_logger branch June 26, 2017 19:11

moolitayer mentioned this pull request Jun 28, 2017

evm:start - UI fails with undefined method silence' for #<MulticastLogger... in evm.log #15463

Closed

imtayadeway mentioned this pull request Jul 5, 2017

Put out some API 🔥 #15510

Merged

This was referenced Feb 12, 2018

Fix MulticastLogger DEBUG mode #16990

Merged

Fix automate specs after MulticastLogger changes #17001

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging to STDOUT in JSON format for containers #15392

Logging to STDOUT in JSON format for containers #15392

bdunne commented Jun 16, 2017 •

edited

Loading

carbonin Jun 19, 2017

bdunne Jun 20, 2017

carbonin commented Jun 19, 2017

gtanzillo commented Jun 19, 2017

imtayadeway Jun 19, 2017

NickLaMuro commented Jun 19, 2017

NickLaMuro Jun 19, 2017

bdunne Jun 23, 2017

jrafanie Jun 19, 2017

Fryguy Jun 19, 2017

bdunne Jun 23, 2017

Fryguy commented Jun 19, 2017

miq-bot commented Jun 19, 2017

bdunne commented Jun 20, 2017

Fryguy Jun 20, 2017

Fryguy Jun 20, 2017

bdunne Jun 23, 2017

jrafanie Jun 22, 2017

bdunne Jun 23, 2017

Fryguy Jun 23, 2017

Fryguy Jun 23, 2017

bdunne Jun 23, 2017

kbrock Jun 23, 2017

Fryguy Jun 23, 2017

bdunne Jun 23, 2017

Fryguy Jun 23, 2017

bdunne Jun 23, 2017

Fryguy Jun 23, 2017

Fryguy commented Jun 23, 2017

miq-bot commented Jun 24, 2017

carbonin left a comment

		@@ -0,0 +1,47 @@
		class ContainerFormatter < Logger::Formatter

Logging to STDOUT in JSON format for containers #15392

Logging to STDOUT in JSON format for containers #15392

Conversation

bdunne commented Jun 16, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carbonin commented Jun 19, 2017

gtanzillo commented Jun 19, 2017

Choose a reason for hiding this comment

NickLaMuro commented Jun 19, 2017

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

Fryguy commented Jun 19, 2017

miq-bot commented Jun 19, 2017

bdunne commented Jun 20, 2017

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

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

Fryguy commented Jun 23, 2017

miq-bot commented Jun 24, 2017

carbonin left a comment

Choose a reason for hiding this comment

bdunne commented Jun 16, 2017 •

edited

Loading