Let VMDBLogger.log_hashes filter out the sensitive value. #135

lfu · 2017-04-25T15:35:27Z

VMDBLogger.log_hashes would log the sensitive value as FILTERED.

@miq-bot assign @gmcculloug
@miq-bot add_label fine/yes, enhancement

gmcculloug · 2017-04-26T18:00:54Z

@Fryguy @jrafanie @bdunne
Looking for feedback on the enhancements to this logging method as we are looking to use it in other areas. Initially in PR ManageIQ/manageiq#14878 but thinking this could also replace the dump_obj calls for most of the providers during provisioning. (The VMware provision has some specific logging requirements, but others could switch to use this common method.)

I think the biggest change here is that the password lines would still be logged, so you could see the key exists, but the value would be marked as "[FILTERED]". Additionally any encrypted values would also be filtered out.

carbonin · 2017-04-26T18:23:44Z

lib/gems/pending/util/vmdb-logger.rb

-      logger.send(level, "  #{l}") unless filter.any? { |f| l.include?(f) }
+      if key = filter.detect { |f| l.include?(f) }
+        l.gsub!(/#{key}.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") }
+      end


This looks like it is changing behavior in an interesting way.

Before this, the entire line which contained a key in options[:filter] was not logged, but now the line has to match a regex and the key name is logged. Why make that change in addition to the filtering for MiqPassword::REGEXP?

Ah I see @gmcculloug mentioned this:

I think the biggest change here is that the password lines would still be logged, so you could see the key exists,

carbonin · 2017-04-26T18:36:54Z

lib/gems/pending/util/vmdb-logger.rb

@@ -108,9 +108,13 @@ def self.log_hashes(logger, h, options = {})
    filter = Array(options[:filter]).flatten.compact.map(&:to_s) << "password"
    filter.uniq!

-    YAML.dump(h).split("\n").each do |l|
+    values = YAML.dump(h).gsub(MiqPassword::REGEXP) { |m| m.gsub($2, "FILTERED") }


Is there a reason this is "FILTERED" and the other is "[FILTERED]" (with square brackets)?

The substitution here ends up looking like v2:{FILTERED} where the braces come from the encrypted string. Adding [...] into the mix seemed useless.

Oh weird, so if we remove the capture groups from that regex then this will probably break. Couldn't we just not even print the v2 part? Is that really that important?

This is based on an existing regex constant from MiqPassword. Would just need to create a new constant there that captures the entire string. Wasn't sure if it was worth it initially.

I think this would still work with the existing regex:

irb(main):002:0> "stuff...v2:{asbvawerfab}..morestuff".gsub(MiqPassword::REGEXP, "[FILTERED]") => "stuff...[FILTERED]..morestuff"

carbonin · 2017-04-26T18:47:11Z

lib/gems/pending/util/vmdb-logger.rb

      next if l[0...3] == '---'
-      logger.send(level, "  #{l}") unless filter.any? { |f| l.include?(f) }
+      if key = filter.detect { |f| l.include?(f) }
+        l.gsub!(/#{key}.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") }


Instead of doing string manipulation here, why not just dup the hash passed in and alter the value before doing the YAML.dump? That seems like it would be much more reliable than this regex dance.

Unless of course you're intentionally trying to match keys like "password-but-not-really-a-password"?

The method was doing a YAML.dump before which means we do not have to be concerned with the depth of embedded objects.

If we stick with the YAML string I think we could do a gsub! for any filters over the whole string outside of the .each loop. Also, would .each_line work here instead of .split("\n")?

So this would match password_for_important_things: s3cr3t, but not root_password: s3cr3t

If we want it to match both we should test for that.

EDIT:

Nevermind, just tested this:

irb(main):008:0> l = "root_password: s3cret" => "root_password: s3cret" irb(main):009:0> l.gsub!(/password.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") } => "root_password: [FILTERED]"

@gmcculloug .each_line would preserve the \n at the end of each line which would print out an extra blank line for each message in the log.

#135 (comment)

carbonin

A few things after talking to @gmcculloug

carbonin · 2017-04-26T19:43:01Z

lib/gems/pending/util/vmdb-logger.rb

      next if l[0...3] == '---'
-      logger.send(level, "  #{l}") unless filter.any? { |f| l.include?(f) }
+      if key = filter.detect { |f| l.include?(f) }
+        l.gsub!(/#{key}.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") }


So this would match password_for_important_things: s3cr3t, but not root_password: s3cr3t

If we want it to match both we should test for that.

EDIT:

Nevermind, just tested this:

irb(main):008:0> l = "root_password: s3cret" => "root_password: s3cret" irb(main):009:0> l.gsub!(/password.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") } => "root_password: [FILTERED]"

carbonin · 2017-04-26T19:43:59Z

spec/util/vmdb-logger_spec.rb

-      expect(buffer.read).to_not include("pa$$w0rd")
+      message = buffer.read
+      expect(message).to_not include("pa$$w0rd")
+      expect(message).to include("FILTERED")


Can we change these specs to all compare against the expected message value directly?

That would make what log_hashes is doing a whole lot more clear.

bdunne · 2017-04-26T20:27:12Z

lib/gems/pending/util/vmdb-logger.rb

+      if key = filter.detect { |f| l.include?(f) }
+        l.gsub!(/#{key}.*: (.+)/) { |m| m.gsub!($1, "[FILTERED]") }
+      end
+      logger.send(level, "  #{l}")


I know this isn't changed in this PR, but what is the value of writing a bunch of individual log lines rather than a single multi-line message?

Fryguy · 2017-05-01T15:42:28Z

My concern is that previously, this was intentionally a pretty blunt object. We filtered line by line and did a line.include? with the filter key, so although you might get false positives, it would kill the line. Now, the regex introduces a potential for something to slip through. I'm wondering if it's cleaner to still just do a line.include?

lfu · 2017-05-03T13:10:12Z

@Fryguy Updated.

Fryguy · 2017-05-03T17:17:59Z

I'm good with this, but I don't know why the bot is not kicking a rubocop check here.

Fryguy · 2017-05-08T20:47:25Z

lib/gems/pending/util/vmdb-logger.rb

      next if l[0...3] == '---'
-      logger.send(level, "  #{l}") unless filter.any? { |f| l.include?(f) }
+      if key = filter.detect { |f| l.include?(f) }


@lfu Can you fix the bot warning...to solve it, just use parens around your if conditional...

if (key = filter.detect { |f| l.include?(f) })

miq-bot · 2017-05-08T20:53:33Z

Checked commit lfu@d5ae4de with ruby 2.2.6, rubocop 0.47.1, and haml-lint 0.20.0
2 files checked, 0 offenses detected
Everything looks fine. ⭐

Let VMDBLogger.log_hashes filter out the sensitive value. (cherry picked from commit 799ba56) https://bugzilla.redhat.com/show_bug.cgi?id=1458434

simaishi · 2017-06-06T16:35:24Z

Fine backport details:

$ git log -1
commit 8f6cd84d1290af555639ac279d408d9ca605b524
Author: Jason Frey <fryguy9@gmail.com>
Date:   Tue May 9 11:08:13 2017 -0400

    Merge pull request #135 from lfu/log_hashes
    
    Let VMDBLogger.log_hashes filter out the sensitive value.
    (cherry picked from commit 799ba5629dc9159a35e61f4d7730af704f874b03)
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1458434

miq-bot assigned gmcculloug Apr 25, 2017

miq-bot added enhancement fine/yes labels Apr 25, 2017

lfu mentioned this pull request Apr 25, 2017

Use $log.log_hashes to filter out sensitive data. ManageIQ/manageiq#14878

Merged

gmcculloug requested review from Fryguy, jrafanie and bdunne April 26, 2017 17:54

carbonin reviewed Apr 26, 2017

View reviewed changes

carbonin previously requested changes Apr 26, 2017

View reviewed changes

carbonin suggested changes Apr 26, 2017

View reviewed changes

bdunne reviewed Apr 26, 2017

View reviewed changes

lfu force-pushed the log_hashes branch 4 times, most recently from bc76743 to 80a59c3 Compare April 27, 2017 13:36

lfu force-pushed the log_hashes branch from 80a59c3 to 4a48e13 Compare May 3, 2017 13:07

carbonin approved these changes May 8, 2017

View reviewed changes

lfu force-pushed the log_hashes branch from 4a48e13 to 1ff246c Compare May 8, 2017 15:56

Fryguy reviewed May 8, 2017

View reviewed changes

Let VMDBLogger.log_hashes filter out the sensitive value.

d5ae4de

lfu force-pushed the log_hashes branch from 1ff246c to d5ae4de Compare May 8, 2017 20:49

Fryguy merged commit 799ba56 into ManageIQ:master May 9, 2017

Fryguy added this to the Sprint 61 Ending May 22, 2017 milestone May 9, 2017

simaishi pushed a commit that referenced this pull request Jun 6, 2017

Merge pull request #135 from lfu/log_hashes

8f6cd84

Let VMDBLogger.log_hashes filter out the sensitive value. (cherry picked from commit 799ba56) https://bugzilla.redhat.com/show_bug.cgi?id=1458434

simaishi added fine/backported and removed fine/yes labels Jun 6, 2017

lfu deleted the log_hashes branch September 29, 2018 14:34

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Let VMDBLogger.log_hashes filter out the sensitive value. #135

Let VMDBLogger.log_hashes filter out the sensitive value. #135

lfu commented Apr 25, 2017 •

edited

Loading

gmcculloug commented Apr 26, 2017

carbonin Apr 26, 2017

carbonin Apr 26, 2017

carbonin Apr 26, 2017

gmcculloug Apr 26, 2017

carbonin Apr 26, 2017

gmcculloug Apr 26, 2017

carbonin Apr 26, 2017

carbonin Apr 26, 2017

carbonin Apr 26, 2017

gmcculloug Apr 26, 2017

carbonin Apr 26, 2017 •

edited

Loading

lfu Apr 26, 2017

carbonin left a comment

carbonin Apr 26, 2017 •

edited

Loading

carbonin Apr 26, 2017

bdunne Apr 26, 2017

Fryguy commented May 1, 2017

lfu commented May 3, 2017

Fryguy commented May 3, 2017

Fryguy May 8, 2017

miq-bot commented May 8, 2017

simaishi commented Jun 6, 2017

Let VMDBLogger.log_hashes filter out the sensitive value. #135

Let VMDBLogger.log_hashes filter out the sensitive value. #135

Conversation

lfu commented Apr 25, 2017 • edited Loading

gmcculloug commented Apr 26, 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

carbonin Apr 26, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carbonin left a comment

Choose a reason for hiding this comment

carbonin Apr 26, 2017 • 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 May 1, 2017

lfu commented May 3, 2017

Fryguy commented May 3, 2017

Choose a reason for hiding this comment

miq-bot commented May 8, 2017

simaishi commented Jun 6, 2017

lfu commented Apr 25, 2017 •

edited

Loading

carbonin Apr 26, 2017 •

edited

Loading

carbonin Apr 26, 2017 •

edited

Loading