Add custom Azure logger #17228

djberg96 · 2018-03-29T02:52:06Z

Because of quirks of the rest-client library (see rest-client/rest-client#34), the $azure_log does not include timestamp information (see ManageIQ/manageiq-providers-azure#177). In addition, the current log includes potentially sensitive information that should be filtered, such as bearer token information. This information also happens to be large, resulting in a rather large log file after a relatively short amount of time.

Applying a custom filter to the logger requires a special subclass, as the formatter is not directly accessible from the $azure_log once created. This subclass sets the formatter so that not only adds the timestamp information, it also filters out Bearer token strings (which are passed along with most Azure REST API requests), SharedKey token strings (used to access Azure's unmanaged storage accounts) and client_id strings (used when initially generating the Bearer token).

Each Bearer token is over 1300 bytes, so this would not only filter potentially sensitive information, it reduces the size of each logged request by over 1k per request.

To test: Add or refresh an Azure cloud provider, and watch the azure.log file.

~~WIP for now until I can figure out why it always seems to set the severity to WARN, and can add some real specs.~~

Added some specs. The WARN is because that's the default setting for the Azure provider.

djberg96 · 2018-03-29T02:52:39Z

@NickLaMuro @Fryguy How's that look?

NickLaMuro · 2018-03-29T19:29:59Z

Seems reasonable to me. Not sure if we want to push having specialized loggers in the main repo, but I think maybe canning that discussion for now is the best choice and moving forward with this.

That said, I think the bot has some suggestions for you 😉

djberg96 · 2018-04-02T16:34:52Z

@NickLaMuro Trying to use utc just causes me grief. I don't understand the current failures, either:

expected "[2018-04-02 16:20:59 +0000] - INFO -- : Hello\n" to match "2018-04-02 16:20:59 +0000"

Note that these specs pass locally.

Fryguy · 2018-04-02T18:08:34Z

lib/vmdb/loggers/azure_logger.rb

+      msg = msg.strip
+      log(level, msg)
+      msg.size
+    end


Why is this necessary? A VMDBLogger is a Logger, which already has the << method defined as you have done here.

Not sure why, but it won't work without it. I assume it's a rest-client issue.

What kind of error? I just tried << on a VMDBLogger and it works.

Ohhh, I see... << "works", but doesn't write out the timestamp, which is the problem in the first place. I'm wondering if this should just be implemented on the underlying VMDBLogger class instead. @NickLaMuro @bdunne thoughts?

I'm wondering if this should just be implemented on the underlying VMDBLogger class instead.

I don't know, seems like a bad idea. The whole point of Logger#<< is to print without formatting:

https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L477-L483

I think it is stupid for rest-client to log via <<, so I think doing this is a targeted class makes more sense. We only want this with loggers where this is a problem (i.e., ones that have to hook into rest-client), and not for every logger in MIQ, because the original behavior of #<< might be desired in some other circumstance.

@bdunne Yes, we have. Take a look at the issue tracker for rest-client. Unfortunately, the project is in poor health.

I have been looking into replacing rest-client where we can (since a couple of dependencies for it our ones we own). That said, it is more a labor of love, and not something on the "official agenda".

@NickLaMuro I'm desperately trying to get azure-armrest switched over to Excon, but it's a lot of work. I should probably make a separate port where I don't try to refactor anything as I go, and just do a straight port to get it working.

@NickLaMuro I actually thinking moving off of rest-client should start getting prioritized a bit higher the longer that rest-client languishes. I think Excon and Faraday are the two best options at this point.

I was just going to use net/http where the additions of provided by other libs aren't really necessary.

Fryguy · 2018-04-02T18:09:04Z

lib/vmdb/loggers/azure_logger.rb

+      @formatter = proc do |severity, datetime, _progname, msg|
+        msg = msg.sub(/Bearer(.*?)\"/, 'Bearer [FILTERED] "')
+        msg = msg.sub(/SharedKey(.*?)\"/, 'SharedKey [FILTERED] "')
+        msg = msg.sub(/client_secret=(.*?)&/, "client_secret=[FILTERED]&")


👍 👍 👍

Fryguy · 2018-04-02T18:09:44Z

lib/vmdb/loggers/azure_logger.rb

+    def initialize(*loggers)
+      super
+
+      @datetime_format = '%Y-%m-%d %H:%M:%S'


Why an alternate datetime_format? Doesn't that make the log messages inconsistent with other VMDBLogger instances?

Ok, I'll remove it.

If for some reason you don't want my_logger.datetime_format to return `nil, you can use the string I provided in the following comment:

#17228 (comment)

Which is what is defaulted in ruby:

https://github.com/ruby/ruby/blob/3be45505/lib/logger.rb#L603-L605

But it does a poor job of making it a constant... which makes me a bit 😡y

Fryguy · 2018-04-02T18:10:06Z

lib/vmdb/loggers/azure_logger.rb

+        msg = msg.sub(/Bearer(.*?)\"/, 'Bearer [FILTERED] "')
+        msg = msg.sub(/SharedKey(.*?)\"/, 'SharedKey [FILTERED] "')
+        msg = msg.sub(/client_secret=(.*?)&/, "client_secret=[FILTERED]&")
+        "[#{datetime}] - #{severity} -- : #{msg}\n"


👎 I don't see why the log message should be completely different from other log messages.

Does it maybe make sense to extend the the VMDBLogger::Formatter#call method here instead then, so we are keeping the same format, but making sure to sub what is needed?

module Vmdb::Loggers class AzureLogger < VMDBLogger def initialize(*loggers) super # pulled from Ruby's `Logger::Formatter`, which is what it defaults to when it is `nil` @datetime_format = "%Y-%m-%dT%H:%M:%S.%6N " @formatter = Vmdb::Loggers::AzureLogger::Formatter.new end # ... class Formatter < VMDBLogger::Formatter def call(severity, datetime, _progname, msg) msg = msg.sub(/Bearer(.*?)\"/, 'Bearer [FILTERED] "') msg = msg.sub(/SharedKey(.*?)\"/, 'SharedKey [FILTERED] "') msg = msg.sub(/client_secret=(.*?)&/, "client_secret=[FILTERED]&") super(severity, datetime, _progname, msg) end end end end

I don't know how to filter the message without having to also specify the format explicitly with a logger instance. Is there a message format I can easily use?

@djberg96 I think you were responding to what @Fryguy was asking not me (posted at roughly the same time it seems). I think what I have supplied would do just that.

Fryguy · 2018-04-02T18:12:38Z

This formatter loses all of the debug information we need like pid, tid, and not to mention that the current format likely won't work in containers mode at all.

NickLaMuro · 2018-04-02T18:31:01Z

This formatter loses all of the debug information we need like pid, tid, and not to mention that the current format likely won't work in containers mode at all.

@Fryguy Good points here in your review and you did a much better job than I did at catching these points...

But... this won't affect containers since it would just get tossed to the lib/vmdb/loggers/container_logger.rb anyway, which will have it's own formatter. That said, that means in the containers the token and other stuff won't be filtered, so that is something we maybe should consider.

Fryguy · 2018-04-02T19:42:20Z

@NickLaMuro Oh good catch...for some reason I though the json was generated from the log message.

Fryguy · 2018-04-02T19:43:22Z

ContainerLogger is actually a really good example of creating a custom formatter that's based on VMDBLogger::Formatter the way @NickLaMuro did in the snippet above.

djberg96 · 2018-04-02T21:25:39Z

@Fryguy Alright, reworked it using @NickLaMuro's Formatter subclass.

Filter SharedKey and client_secret, add custom << method. Added some spaces back into replacement strings, and added some specs. Reworked to subclass Formatter.

miq-bot · 2018-04-03T16:10:50Z

Checked commit https://github.com/djberg96/manageiq/commit/dcdc4d60a6a65046321ba1111b772285d360f174 with ruby 2.3.3, rubocop 0.52.1, haml-lint 0.20.0, and yamllint 1.10.0
3 files checked, 0 offenses detected
Everything looks fine. ⭐

NickLaMuro

Looks good to me.

Fryguy · 2018-04-03T18:00:51Z

I am good with this. Ultimately, I'd like this to be pluggable, but we should just add it to the list : #14840.

djberg96 · 2018-11-27T17:51:08Z

@simaishi Please backport this to the G release: https://bugzilla.redhat.com/show_bug.cgi?id=1640718

djberg96 · 2018-11-27T17:51:41Z

@miq-bot add_label gaprindashvili/yes

simaishi · 2018-11-27T17:56:41Z

@djberg96 I can't backport PR to Gaprindashvili branch unless BZ is approved for a particular G-release by bug triage...

djberg96 · 2018-12-18T18:02:26Z

@simaishi I think it's been approved now. :)

simaishi · 2018-12-18T18:09:37Z

@djberg96 It's still not approved for G-branch...

"Approved" BZs will have "Target Release" set to a particular release (e.g. 5.9.6), and "blocker" flag set. Since the BZ's target release was changed, this will be included only in Hammer and later builds.

djberg96 · 2018-12-18T18:13:38Z

@dmetzger57 I need this approved for G branch or I can't close the BZ.

simaishi · 2018-12-18T18:15:59Z

@djberg96 I already took care of the BZ.

djberg96 mentioned this pull request Mar 29, 2018

Azure Debug logging does not contain timestamps ManageIQ/manageiq-providers-azure#177

Closed

miq-bot added the wip label Mar 29, 2018

djberg96 changed the title ~~[WIP] Add custom Azure logger~~ Add custom Azure logger Mar 29, 2018

miq-bot removed the wip label Mar 29, 2018

NickLaMuro mentioned this pull request Apr 2, 2018

Fix MulticastLogger#datetime_formatter #17223

Merged

Fryguy reviewed Apr 2, 2018

View reviewed changes

Add custom Azure logger.

dcdc4d6

Filter SharedKey and client_secret, add custom << method. Added some spaces back into replacement strings, and added some specs. Reworked to subclass Formatter.

NickLaMuro approved these changes Apr 3, 2018

View reviewed changes

Fryguy merged commit 2652592 into ManageIQ:master Apr 3, 2018

Fryguy added bug providers/microsoft/cloud labels Apr 3, 2018

Fryguy added this to the Sprint 83 Ending Apr 9, 2018 milestone Apr 3, 2018

Fryguy self-assigned this Apr 3, 2018

Fryguy modified the milestones: Sprint 83 Ending Apr 9, 2018, Roadmap Apr 3, 2018

Fryguy mentioned this pull request Apr 3, 2018

Pluggable Providers TODO #14840

Closed

38 tasks

djberg96 mentioned this pull request Apr 5, 2018

[WIP] Add timestamp to logging ManageIQ/manageiq-providers-azure#203

Closed

miq-bot added the gaprindashvili/yes label Nov 27, 2018

Fryguy added the providers/cloud label Jan 24, 2020

Add custom Azure logger #17228

Add custom Azure logger #17228

Conversation

djberg96 commented Mar 29, 2018 • edited Loading

djberg96 commented Mar 29, 2018

NickLaMuro commented Mar 29, 2018

djberg96 commented Apr 2, 2018

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

Choose a reason for hiding this comment

NickLaMuro Apr 2, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Fryguy commented Apr 2, 2018

NickLaMuro commented Apr 2, 2018 • edited Loading

Fryguy commented Apr 2, 2018

Fryguy commented Apr 2, 2018

djberg96 commented Apr 2, 2018

miq-bot commented Apr 3, 2018

NickLaMuro left a comment

Choose a reason for hiding this comment

Fryguy commented Apr 3, 2018

djberg96 commented Nov 27, 2018

djberg96 commented Nov 27, 2018

simaishi commented Nov 27, 2018

djberg96 commented Dec 18, 2018

simaishi commented Dec 18, 2018

djberg96 commented Dec 18, 2018

simaishi commented Dec 18, 2018

djberg96 commented Mar 29, 2018 •

edited

Loading

NickLaMuro Apr 2, 2018 •

edited

Loading

NickLaMuro commented Apr 2, 2018 •

edited

Loading