Wiring audit event proxy to send events correctly to the audit_reporter

12 files changed, 290 insertions, 170 deletions

diff --git a/lib/chef/application/solo.rb b/lib/chef/application/solo.rb
index 6e568ddbb1..50f7f5c5d4 100644
--- a/lib/chef/application/solo.rb
+++ b/lib/chef/application/solo.rb
@@ -211,6 +211,9 @@ class Chef::Application::Solo < Chef::Application
       config_fetcher = Chef::ConfigFetcher.new(Chef::Config[:json_attribs])
       @chef_client_json = config_fetcher.fetch_json
     end
+
+    # If we don't specify this, solo will try to perform the audits
+    Chef::Config[:audit_mode] = false
   end
 
   def setup_application
diff --git a/lib/chef/audit.rb b/lib/chef/audit.rb
index 9d0a2a70ed..ed8db93d96 100644
--- a/lib/chef/audit.rb
+++ b/lib/chef/audit.rb
@@ -26,5 +26,4 @@ require 'serverspec/subject'
 require 'specinfra'
 
 require 'chef/dsl/audit'
-require 'chef/audit/chef_json_formatter'
 require 'chef/audit/runner'
diff --git a/lib/chef/audit/audit_event_proxy.rb b/lib/chef/audit/audit_event_proxy.rb
index d56c7f0ac5..71d1e2aa50 100644
--- a/lib/chef/audit/audit_event_proxy.rb
+++ b/lib/chef/audit/audit_event_proxy.rb
@@ -3,11 +3,10 @@ RSpec::Support.require_rspec_core "formatters/base_text_formatter"
 class Chef
   class Audit
     class AuditEventProxy < ::RSpec::Core::Formatters::BaseFormatter
-      ::RSpec::Core::Formatters.register self, :example_group_started, :example_group_finished,
-                                         :example_passed, :example_failed
+      ::RSpec::Core::Formatters.register self, :stop, :example_group_started
 
       # TODO I don't like this, but I don't see another way to pass this in
-      # see configuration.rb#L671 and formatters.rb#L129
+      # see rspec files configuration.rb#L671 and formatters.rb#L129
       def self.events=(events)
         @@events = events
       end
@@ -17,26 +16,61 @@ class Chef
       end
 
       def example_group_started(notification)
-        events.control_group_start(notification.group.description.strip)
+        if notification.group.parent_groups.size == 1
+          # top level controls block
+          desc = notification.group.description
+          Chef::Log.debug("Entered controls block named #{desc}")
+          events.control_group_started(desc)
+        end
       end
 
-      def example_group_finished(_notification)
-        events.control_group_end
+      def stop(notification)
+        Chef::Log.info("Successfully executed all controls blocks and contained examples")
+        notification.examples.each do |example|
+          control_group_name, control_data = build_control_from(example)
+          e = example.exception
+          if e
+            events.control_example_failure(control_group_name, control_data, e)
+          else
+            events.control_example_success(control_group_name, control_data)
+          end
+        end
       end
 
-      def example_passed(passed)
-        events.control_example_success(passed.example.description.strip)
-      end
+      private
 
-      def example_failed(failed)
-        events.control_example_failure(failed.example.description.strip, failed.example.execution_result.exception)
-      end
+      def build_control_from(example)
+        described_class = example.metadata[:described_class]
+        if described_class
+          resource_type = described_class.class.name.split(':')[-1]
+          # TODO submit github PR to expose this
+          resource_name = described_class.instance_variable_get(:@name)
+        end
 
-      private
+        # The following code builds up the context - the list of wrapping `describe` or `control` blocks
+        describe_groups = []
+        group = example.metadata[:example_group]
+        # If the innermost block has a resource instead of a string, don't include it in context
+        describe_groups.unshift(group[:description]) if described_class.nil?
+        group = group[:parent_example_group]
+        while !group.nil?
+          describe_groups.unshift(group[:description])
+          group = group[:parent_example_group]
+        end
+
+        # We know all of our examples each live in a top-level `controls` block - get this name now
+        outermost_group_desc = describe_groups.shift
 
-      def example_group_chain
-        example_group.parent_groups.reverse
+        return outermost_group_desc, {
+            :name => example.description,
+            :desc => example.full_description,
+            :resource_type => resource_type,
+            :resource_name => resource_name,
+            :context => describe_groups,
+            :line_number => example.metadata[:line_number]
+        }
       end
+
     end
   end
 end
diff --git a/lib/chef/audit/audit_reporter.rb b/lib/chef/audit/audit_reporter.rb
new file mode 100644
index 0000000000..b1c9d30bfc
--- /dev/null
+++ b/lib/chef/audit/audit_reporter.rb
@@ -0,0 +1,135 @@
+#
+# Auther:: Tyler Ball (<tball@getchef.com>)
+#
+# Copyright:: Copyright (c) 2014 Opscode, Inc.
+# License:: Apache License, Version 2.0
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+
+require 'chef/event_dispatch/base'
+require 'chef/audit/control_group_data'
+
+class Chef
+  class Audit
+    class AuditReporter < EventDispatch::Base
+
+      attr_reader :rest_client, :audit_data, :ordered_control_groups
+      private :rest_client, :audit_data, :ordered_control_groups
+
+      PROTOCOL_VERSION = '0.1.0'
+
+      def initialize(rest_client)
+        if Chef::Config[:audit_mode] == false
+          @audit_enabled = false
+        else
+          @audit_enabled = true
+        end
+        @rest_client = rest_client
+        # Ruby 1.9.3 and above "enumerate their values in the order that the corresponding keys were inserted."
+        @ordered_control_groups = Hash.new
+      end
+
+      def audit_phase_start(run_status)
+        Chef::Log.debug("Audit Reporter starting")
+        @audit_data = AuditData.new(run_status.node.name, run_status.run_id)
+      end
+
+      def audit_phase_complete
+        Chef::Log.debug("Audit Reporter completed successfully without errors")
+        ordered_control_groups.each do |name, control_group|
+          audit_data.add_control_group(control_group)
+        end
+        post_auditing_data
+      end
+
+      # If the audit phase failed, its because there was some kind of error in the framework
+      # that runs tests - normal errors are interpreted as EXAMPLE failures and captured.
+      def audit_phase_failed(error)
+        # The stacktrace information has already been logged elsewhere
+        Chef::Log.error("Audit Reporter failed - sending error to server with available example information")
+        ordered_control_groups.each do |name, control_group|
+          audit_data.add_control_group(control_group)
+        end
+        post_auditing_data(error)
+      end
+
+      def control_group_started(name)
+        if ordered_control_groups.has_key?(name)
+          raise AuditControlGroupDuplicate.new(name)
+        end
+        ordered_control_groups.store(name, ControlGroupData.new(name))
+      end
+
+      def control_example_success(control_group_name, example_data)
+        control_group = ordered_control_groups[control_group_name]
+        control_group.example_success(example_data)
+      end
+
+      def control_example_failure(control_group_name, example_data, error)
+        control_group = ordered_control_groups[control_group_name]
+        control_group.example_failure(example_data, error.message)
+      end
+
+      def auditing_enabled?
+        @audit_enabled
+      end
+
+      private
+
+      def post_auditing_data(error = nil)
+        if auditing_enabled?
+          audit_history_url = "controls"
+          Chef::Log.info("Sending audit report (run-id: #{audit_data.run_id})")
+          run_data = audit_data.to_hash
+
+          if error
+            run_data[:error] = "#{error.class.to_s}: #{error.message}\n#{error.backtrace.join("\n")}"
+          end
+
+          Chef::Log.debug run_data.inspect
+          compressed_data = encode_gzip(Chef::JSONCompat.to_json(run_data))
+          Chef::Log.debug("Sending compressed audit data...")
+          # Since we're posting compressed data we can not directly call post_rest which expects JSON
+          audit_url = rest_client.create_url(audit_history_url)
+          begin
+            puts Chef::JSONCompat.to_json_pretty(run_data)
+            rest_client.raw_http_request(:POST, audit_url, headers({'Content-Encoding' => 'gzip'}), compressed_data)
+          rescue StandardError => e
+            if e.respond_to? :response
+              error_file = "failed-audit-data.json"
+              Chef::FileCache.store(error_file, Chef::JSONCompat.to_json_pretty(run_data), 0640)
+              Chef::Log.error("Failed to post audit report to server (HTTP #{e.response.code}), saving to #{Chef::FileCache.load(error_file, false)}")
+            else
+              Chef::Log.error("Failed to post audit report to server (#{e})")
+            end
+          end
+        else
+          Chef::Log.debug("Server doesn't support audit report, skipping.")
+        end
+      end
+
+      def headers(additional_headers = {})
+        options = {'X-Ops-Audit-Report-Protocol-Version' => PROTOCOL_VERSION}
+        options.merge(additional_headers)
+      end
+
+      def encode_gzip(data)
+        "".tap do |out|
+          Zlib::GzipWriter.wrap(StringIO.new(out)){|gz| gz << data }
+        end
+      end
+
+    end
+  end
+end
diff --git a/lib/chef/audit/chef_json_formatter.rb b/lib/chef/audit/chef_json_formatter.rb
deleted file mode 100644
index 50dfbffbb3..0000000000
--- a/lib/chef/audit/chef_json_formatter.rb
+++ /dev/null
@@ -1,79 +0,0 @@
-RSpec::Support.require_rspec_core "formatters/base_formatter"
-require 'chef/audit/control_group_data'
-require 'ffi_yajl'
-
-class Chef
-  class Audit
-    class ChefJsonFormatter < ::RSpec::Core::Formatters::BaseFormatter
-      ::RSpec::Core::Formatters.register self, :example_group_started, :stop, :close
-
-      attr_reader :control_group_data
-
-      # TODO hopefully the runner can take care of this for us since there won't be an outer-most
-      # control group
-      @@outer_example_group_found = false
-
-      def initialize(output)
-        super
-      end
-
-      # Invoked for each `control`, `describe`, `context` block
-      def example_group_started(notification)
-        unless @@outer_example_group_found
-          @control_group_data = ControlGroupData.new(notification.group.description)
-          @@outer_example_group_found = true
-        end
-      end
-
-      def stop(notification)
-        notification.examples.each do |example|
-          control_data = build_control_from(example)
-          e = example.exception
-          if e
-            control = control_group_data.example_failure(e.message, control_data)
-          else
-            control = control_group_data.example_success(control_data)
-          end
-          control.line_number = example.metadata[:line_number]
-        end
-      end
-
-      def close(notification)
-        output.write FFI_Yajl::Encoder.encode(control_group_data.to_hash, pretty: true)
-        output.close if IO === output && output != $stdout
-      end
-
-      private
-
-      def build_control_from(example)
-        described_class = example.metadata[:described_class]
-        if described_class
-          resource_type = described_class.class.name.split(':')[-1]
-          # TODO submit github PR to expose this
-          resource_name = described_class.instance_variable_get(:@name)
-        end
-
-        describe_groups = []
-        group = example.metadata[:example_group]
-        # If the innermost block has a resource instead of a string, don't include it in context
-        describe_groups.unshift(group[:description]) if described_class.nil?
-        group = group[:parent_example_group]
-        while !group.nil?
-          describe_groups.unshift(group[:description])
-          group = group[:parent_example_group]
-        end
-        # TODO remove this when we're no longer wrapping everything with "mysql audit"
-        describe_groups.shift
-
-        {
-            :name => example.description,
-            :desc => example.full_description,
-            :resource_type => resource_type,
-            :resource_name => resource_name,
-            :context => describe_groups
-        }
-      end
-
-    end
-  end
-end
diff --git a/lib/chef/audit/control_group_data.rb b/lib/chef/audit/control_group_data.rb
index fc758e45ba..e19a6e1a15 100644
--- a/lib/chef/audit/control_group_data.rb
+++ b/lib/chef/audit/control_group_data.rb
@@ -1,5 +1,29 @@
+require 'securerandom'
+
 class Chef
   class Audit
+    class AuditData
+      attr_reader :node_name, :run_id, :control_groups
+
+      def initialize(node_name, run_id)
+        @node_name = node_name
+        @run_id = run_id
+        @control_groups = []
+      end
+
+      def add_control_group(control_group)
+        control_groups << control_group
+      end
+
+      def to_hash
+        {
+            :node_name => node_name,
+            :run_id => run_id,
+            :control_groups => control_groups.collect { |c| c.to_hash }
+        }
+      end
+    end
+
     class ControlGroupData
       attr_reader :name, :status, :number_success, :number_failed, :controls
 
@@ -12,18 +36,18 @@ class Chef
       end
 
 
-      def example_success(opts={})
+      def example_success(control_data)
         @number_success += 1
-        control = create_control(opts)
+        control = create_control(control_data)
         control.status = "success"
         controls << control
         control
       end
 
-      def example_failure(details=nil, opts={})
+      def example_failure(control_data, details)
         @number_failed += 1
         @status = "failure"
-        control = create_control(opts)
+        control = create_control(control_data)
         control.details = details if details
         control.status = "failure"
         controls << control
@@ -31,53 +55,69 @@ class Chef
       end
 
       def to_hash
+        # We sort it so the examples appear in the output in the same order
+        # they appeared in the recipe
         controls.sort! {|x,y| x.line_number <=> y.line_number}
-        {
-            :control_group => {
-                :name => name,
-                :status => status,
-                :number_success => number_success,
-                :number_failed => number_failed,
-                :controls => controls.collect { |c| c.to_hash }
-            }
+        h = {
+              :name => name,
+              :status => status,
+              :number_success => number_success,
+              :number_failed => number_failed,
+              :controls => controls.collect { |c| c.to_hash }
         }
+        add_display_only_data(h)
       end
 
       private
 
-      def create_control(opts={})
-        name = opts[:name]
-        resource_type = opts[:resource_type]
-        resource_name = opts[:resource_name]
-        context = opts[:context]
-        ControlData.new(name, resource_type, resource_name, context)
+      def create_control(control_data)
+        name = control_data[:name]
+        resource_type = control_data[:resource_type]
+        resource_name = control_data[:resource_name]
+        context = control_data[:context]
+        line_number = control_data[:line_number]
+        # TODO make this smarter with splat arguments so if we start passing in more control_data
+        # I don't have to modify code in multiple places
+        ControlData.new(name, resource_type, resource_name, context, line_number)
+      end
+
+      # The id and control sequence number are ephemeral data - they are not needed
+      # to be persisted and can be regenerated at will.  They are only needed
+      # for display purposes.
+      def add_display_only_data(group)
+        group[:id] = SecureRandom.uuid
+        group[:controls].collect!.with_index do |c, i|
+          # i is zero-indexed, and we want the display one-indexed
+          c[:sequence_number] = i+1
+          c
+        end
+        group
       end
 
     end
 
     class ControlData
-      attr_reader :name, :resource_type, :resource_name, :context
+      attr_reader :name, :resource_type, :resource_name, :context, :line_number
       attr_accessor :status, :details
-      # TODO this only helps with debugging
-      attr_accessor :line_number
 
-      def initialize(name, resource_type, resource_name, context)
+      def initialize(name, resource_type, resource_name, context, line_number)
         @context = context
         @name = name
         @resource_type = resource_type
         @resource_name = resource_name
+        @line_number = line_number
       end
 
       def to_hash
-        ret = {
+        h = {
             :name => name,
             :status => status,
             :details => details,
             :resource_type => resource_type,
             :resource_name => resource_name
         }
-        ret[:context] = context || []
-        ret
+        h[:context] = context || []
+        h
       end
     end
 
diff --git a/lib/chef/audit/runner.rb b/lib/chef/audit/runner.rb
index 4a76b7e65b..4059741359 100644
--- a/lib/chef/audit/runner.rb
+++ b/lib/chef/audit/runner.rb
@@ -18,7 +18,6 @@
 
 require 'chef/audit'
 require 'chef/audit/audit_event_proxy'
-require 'chef/audit/chef_json_formatter'
 require 'chef/config'
 
 class Chef
@@ -72,6 +71,7 @@ class Chef
         configuration.backtrace_exclusion_patterns.push(Regexp.new("/Users".gsub("/", File::SEPARATOR)))
         configuration.backtrace_exclusion_patterns.push(Regexp.new("(eval)"))
         configuration.color = Chef::Config[:color]
+        configuration.expose_dsl_globally = false
 
         add_formatters
         disable_should_syntax
@@ -80,9 +80,8 @@ class Chef
 
       def add_formatters
         configuration.add_formatter(RSpec::Core::Formatters::DocumentationFormatter)
-        configuration.add_formatter(Chef::Audit::ChefJsonFormatter)
-        #configuration.add_formatter(Chef::Audit::AuditEventProxy)
-        #Chef::Audit::AuditEventProxy.events = run_context.events
+        configuration.add_formatter(Chef::Audit::AuditEventProxy)
+        Chef::Audit::AuditEventProxy.events = run_context.events
       end
 
       # Explicitly disable :should syntax.
diff --git a/lib/chef/client.rb b/lib/chef/client.rb
index bf8c83eee2..b27a2b693d 100644
--- a/lib/chef/client.rb
+++ b/lib/chef/client.rb
@@ -44,6 +44,7 @@ require 'chef/formatters/doc'
 require 'chef/formatters/minimal'
 require 'chef/version'
 require 'chef/resource_reporter'
+require 'chef/audit/audit_reporter'
 require 'chef/run_lock'
 require 'chef/policy_builder'
 require 'chef/request_id'
@@ -210,6 +211,17 @@ class Chef
       end
     end
 
+    # Resource repoters send event information back to the chef server for processing.
+    # Can only be called after we have a @rest object
+    def register_reporters
+      [
+        Chef::ResourceReporter.new(rest),
+        Chef::Audit::AuditReporter.new(rest)
+      ].each do |r|
+        events.register(r)
+      end
+    end
+
     # Instantiates a Chef::Node object, possibly loading the node's prior state
     # when using chef-client. Delegates to policy_builder
     #
@@ -296,9 +308,7 @@ class Chef
       end
       # We now have the client key, and should use it from now on.
       @rest = Chef::REST.new(config[:chef_server_url], client_name, config[:client_key])
-      # TODO register this where we register all other event listeners
-      @resource_reporter = Chef::ResourceReporter.new(@rest)
-      @events.register(@resource_reporter)
+      register_reporters
     rescue Exception => e
       # TODO: munge exception so a semantic failure message can be given to the
       # user
@@ -320,6 +330,7 @@ class Chef
           runner.converge
           @events.converge_complete
         rescue Exception => e
+          Chef::Log.error("Converge failed with error message #{e.message}")
           @events.converge_failed(e)
           converge_exception = e
         end
@@ -340,15 +351,16 @@ class Chef
       converge_exception
     end
 
-    # TODO are failed audits going to raise exceptions, or only be handled by the reporters?
     def run_audits(run_context)
       audit_exception = nil
       begin
-        @events.audit_phase_start(run_context)
+        @events.audit_phase_start(run_status)
+        Chef::Log.info("Starting audit phase")
         auditor = Chef::Audit::Runner.new(run_context)
         auditor.run
         @events.audit_phase_complete
       rescue Exception => e
+        Chef::Log.error("Audit phase failed with error message #{e.message}")
         @events.audit_phase_failed(e)
         audit_exception = e
       end
@@ -429,8 +441,8 @@ class Chef
 
         run_context = setup_run_context
 
-        converge_error = converge_and_save(run_context)
-        audit_error = run_audits(run_context)
+        converge_error = converge_and_save(run_context) unless (Chef::Config[:audit_mode] == true)
+        audit_error = run_audits(run_context) unless (Chef::Config[:audit_mode] == false)
 
         if converge_error || audit_error
           e = Chef::Exceptions::RunFailedWrappingError.new(converge_error, audit_error)
diff --git a/lib/chef/dsl/audit.rb b/lib/chef/dsl/audit.rb
index 42a1927efb..1849b65633 100644
--- a/lib/chef/dsl/audit.rb
+++ b/lib/chef/dsl/audit.rb
@@ -29,6 +29,8 @@ class Chef
       # Adds the controls group and block (containing controls to execute) to the runner's list of pending examples
       def controls(*args, &block)
         raise ::Chef::Exceptions::NoAuditsProvided unless block
+        name = args[0]
+        raise AuditNameMissing if name.nil? || name.empty?
 
         run_context.controls_groups << ::RSpec::Core::ExampleGroup.__controls__(*args, &block)
       end
diff --git a/lib/chef/event_dispatch/base.rb b/lib/chef/event_dispatch/base.rb
index e55f752065..695e31cf2e 100644
--- a/lib/chef/event_dispatch/base.rb
+++ b/lib/chef/event_dispatch/base.rb
@@ -230,7 +230,7 @@ class Chef
       end
 
       # Called before audit phase starts
-      def audit_phase_start(run_context)
+      def audit_phase_start(run_status)
       end
 
       # Called when audit phase successfully finishes
@@ -243,19 +243,16 @@ class Chef
       def audit_phase_failed(exception)
       end
 
-      def control_group_start(name)
-        # TODO use this only for stdout formatting, controls indentation
+      # Signifies the start of a `controls` block with a defined name
+      def control_group_started(name)
       end
 
-      def control_group_end
+      # An example in a `controls` block completed successfully
+      def control_example_success(control_group_name, example_data)
       end
 
-      def control_example_success(description)
-        # TODO Use this for both stdout and resource_reporter, need to pass ancestor tree for resource_reporter
-        # but that is ignored by stdout
-      end
-
-      def control_example_failure(description, exception)
+      # An example in a `controls` block failed with the provided error
+      def control_example_failure(control_group_name, example_data, error)
       end
 
       # TODO: need events for notification resolve?
diff --git a/lib/chef/exceptions.rb b/lib/chef/exceptions.rb
index 842910f2ae..9fae1d566f 100644
--- a/lib/chef/exceptions.rb
+++ b/lib/chef/exceptions.rb
@@ -385,6 +385,12 @@ class Chef
       end
     end
 
+    class AuditControlGroupDuplicate < RuntimeError
+      def initialize(name)
+        super "Audit control group with name '#{name}' has already been defined"
+      end
+    end
+    class AuditNameMissing < RuntimeError; end
     class NoAuditsProvided < RuntimeError
       def initialize
         super "You must provide a block with audits"
diff --git a/lib/chef/formatters/doc.rb b/lib/chef/formatters/doc.rb
index d9c9124713..09d04f3aae 100644
--- a/lib/chef/formatters/doc.rb
+++ b/lib/chef/formatters/doc.rb
@@ -162,20 +162,16 @@ class Chef
       #############
 
       # Called before audit phase starts
-      def audit_phase_start(run_context)
+      def audit_phase_start(run_status)
         puts_line ""
         puts_line "++ Audit phase starting ++"
       end
 
-      # Called when audit phase successfully finishes
       def audit_phase_complete
         puts_line ""
         puts_line "++ Audit phase ended ++ "
       end
 
-      # Called if there is an uncaught exception during the audit phase.  The audit runner should
-      # be catching and handling errors from the examples, so this is only uncaught errors (like
-      # bugs in our handling code)
       def audit_phase_failed(error)
         puts_line ""
         puts_line "Audit phase exception:"
@@ -187,30 +183,6 @@ class Chef
         end
       end
 
-      def control_group_start(name)
-        puts_line "Control group #{name} started"
-        indent
-      end
-
-      def control_group_end
-        unindent
-      end
-
-      def control_example_success(description)
-        puts_line "SUCCESS - #{description}"
-      end
-
-      def control_example_failure(description, error)
-        puts_line "FAILURE - #{description}"
-        indent
-        # TODO error_mapper ?
-        puts_line "#{error.message}"
-        # error.backtrace.each do |l|
-        #   puts_line l
-        # end
-        unindent
-      end
-
       # Called before action is executed on a resource.
       def resource_action_start(resource, action, notification_type=nil, notifier=nil)
         if resource.cookbook_name && resource.recipe_name