add metadata to log messages

Signed-off-by: Thom May <thom@chef.io>

3 files changed, 65 insertions, 2 deletions

diff --git a/spec/mixlib/log/child_spec.rb b/spec/mixlib/log/child_spec.rb
index daf3734..eef2ce9 100644
--- a/spec/mixlib/log/child_spec.rb
+++ b/spec/mixlib/log/child_spec.rb
@@ -39,10 +39,49 @@ RSpec.describe Mixlib::Log::Child do
     expect(io.string).to match(/a message$/)
   end
 
+  context "with structured data" do
+    it "can be created with metadata" do
+      expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true" })
+      Logit.with_child({ child: "true" }) { |l| l.warn("a message") }
+    end
+
+    it "a message can be logged" do
+      expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true" })
+      Logit.with_child { |l| l.warn("a message", data: { child: "true" }) }
+    end
+
+    context "merges properly" do
+      it "in the simple case" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", meta: "data" })
+        Logit.with_child(meta: "data") { |l| l.warn("a message", data: { child: "true" }) }
+      end
+
+      it "when overwriting" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", meta: "overwritten" })
+        Logit.with_child(meta: "data") { |l| l.warn("a message", data: { child: "true", meta: "overwritten" }) }
+      end
+    end
+
+    context "when receiving a message from a child" do
+      it "passes data on" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", parent: "first" })
+        child.metadata = { parent: "first" }
+        child.with_child { |l| l.warn("a message", data: { child: "true" }) }
+      end
+
+      it "merges its own data" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", parent: "second" })
+        child.metadata = { parent: "first" }
+        child.with_child { |l| l.warn("a message", data: { child: "true", parent: "second" }) }
+      end
+    end
+  end
+
   context "sends a message to the parent" do
     %i{ debug info warn error fatal }.each do |level|
       it "at #{level}" do
-        expect(Logit).to receive(:pass).with(level, "a #{level} message", nil)
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[level], "a #{level} message", nil, data: {})
+        Logit.level = level
         child.send(level, "a #{level} message")
       end
     end
diff --git a/spec/mixlib/log/formatter_spec.rb b/spec/mixlib/log/formatter_spec.rb
index dd3ce25..16e45af 100644
--- a/spec/mixlib/log/formatter_spec.rb
+++ b/spec/mixlib/log/formatter_spec.rb
@@ -48,4 +48,17 @@ RSpec.describe Mixlib::Log::Formatter do
     expect(@formatter.call("monkey", Time.new, "test", "mos def")).to eq("monkey: mos def\n")
   end
 
+  context "with structured data" do
+    let(:data) { {} }
+
+    it "should format a message" do
+      data[:msg] = "nuthin new"
+      expect(@formatter.msg2str(data)).to eq("nuthin new")
+    end
+
+    it "should format an exception" do
+      data[:err] = IOError.new("legendary roots crew")
+      expect(@formatter.msg2str(data)).to eq("legendary roots crew (IOError)\n")
+    end
+  end
 end
diff --git a/spec/mixlib/log_spec.rb b/spec/mixlib/log_spec.rb
index 69eebd5..ac4932d 100644
--- a/spec/mixlib/log_spec.rb
+++ b/spec/mixlib/log_spec.rb
@@ -23,9 +23,19 @@ require "spec_helper"
 
 class LoggerLike
   attr_accessor :level
-  attr_reader :messages
+  attr_reader :messages, :data
   def initialize
     @messages = ""
+    @data = []
+  end
+
+  def add_data(severity, message = nil, progname = nil, data: {})
+    @messages << message
+    @data << data
+  end
+
+  def add(severity, message = nil, progname = nil, data: {})
+    @messages << message
   end
 
   [:debug, :info, :warn, :error, :fatal].each do |method_name|
@@ -64,6 +74,7 @@ RSpec.describe Mixlib::Log do
   it "uses the logger provided when initialized with a logger like object" do
     logger = LoggerLike.new
     Logit.init(logger)
+    Logit.level = :debug
     Logit.debug "qux"
     expect(logger.messages).to match(/qux/)
   end