Audit details (#1)

Audit details

* Audit logs and broadcasts accept `details` whose values are included as log tags and MRSK_* env vars passed to the broadcast command
* Commands may return execution options to the CLI in their args list
* Introduce `mrsk broadcast` helper for sending audit broadcasts
* Report UTC time, not local time, in audit logs. Standardize on ISO 8601 format

README.md

@@ -677,14 +677,20 @@ That'll post a line like follows to a preconfigured chatbot in Basecamp:
 [My App] [dhh] Rolled back to version d264c4e92470ad1bd18590f04466787262f605de
 ```
 
-In addition to the formatted message, MRSK sets a number of environment variables with the components of the broadcast.
+`MRSK_*` environment variables are available to the broadcast command for
-You can use these (rather than the command argument) if you want more control over how the message is formatted.
+fine-grained audit reporting, e.g. for triggering deployment reports or
-MRSK currently sets:
+firing a JSON webhook. These variables include:
+- `MRSK_RECORDED_AT` - UTC timestamp in ISO 8601 format, e.g. `2023-04-14T17:07:31Z`
+- `MRSK_PERFORMER` - the local user performing the command (from `whoami`)
+- `MRSK_MESSAGE` - the full audit message, e.g. "Deployed app@150b24f"
+- `MRSK_DESTINATION` - optional: destination, e.g. "staging"
+- `MRSK_ROLE` - optional: role targeted, e.g. "web"
 
-- `MRSK_PERFORMER` - the user performing the command
+Use `mrsk broadcast` to test and troubleshoot your broadcast command:
-- `MRSK_DESTINATION` - the destination
+
-- `MRSK_ROLE` - the specific role being targetted, if any
+```bash
-- `MRSK_MESSAGE` - full text of the action (e.g. "Deployed app@150b24f")
+mrsk broadcast -m "test audit message"
+```
 
 ### Healthcheck
 

lib/mrsk/cli/app.rb

@@ -60,7 +60,7 @@ class Mrsk::Cli::App < Mrsk::Cli::Base
         roles = MRSK.roles_on(host)
 
         roles.each do |role|
-          execute *MRSK.auditor(role: role).record("Stopped app"), verbosity: :debug
+          execute *MRSK.auditor.record("Stopped app", role: role), verbosity: :debug
           execute *MRSK.app(role: role).stop, raise_on_non_zero_exit: false
         end
       end
@@ -107,7 +107,7 @@ class Mrsk::Cli::App < Mrsk::Cli::Base
           roles = MRSK.roles_on(host)
 
           roles.each do |role|
-            execute *MRSK.auditor(role: role).record("Executed cmd '#{cmd}' on app version #{version}"), verbosity: :debug
+            execute *MRSK.auditor.record("Executed cmd '#{cmd}' on app version #{version}", role: role), verbosity: :debug
             puts_by_host host, capture_with_info(*MRSK.app(role: role).execute_in_existing_container(cmd))
           end
         end
@@ -214,7 +214,7 @@ class Mrsk::Cli::App < Mrsk::Cli::Base
         roles = MRSK.roles_on(host)
 
         roles.each do |role|
-          execute *MRSK.auditor(role: role).record("Removed app container with version #{version}"), verbosity: :debug
+          execute *MRSK.auditor.record("Removed app container with version #{version}", role: role), verbosity: :debug
           execute *MRSK.app(role: role).remove_container(version: version)
         end
       end
@@ -228,7 +228,7 @@ class Mrsk::Cli::App < Mrsk::Cli::Base
         roles = MRSK.roles_on(host)
 
         roles.each do |role|
-          execute *MRSK.auditor(role: role).record("Removed all app containers"), verbosity: :debug
+          execute *MRSK.auditor.record("Removed all app containers", role: role), verbosity: :debug
           execute *MRSK.app(role: role).remove_containers
         end
       end

lib/mrsk/cli/base.rb

@@ -73,9 +73,7 @@ module Mrsk::Cli
       end
 
       def audit_broadcast(line)
-        if broadcast = MRSK.auditor.broadcast(line)
+        run_locally { execute *MRSK.auditor.broadcast(line), verbosity: :debug }
-          system(MRSK.auditor.broadcast_environment(line), broadcast)
-        end
       end
 
       def with_lock

lib/mrsk/cli/main.rb

@@ -200,6 +200,13 @@ class Mrsk::Cli::Main < Mrsk::Cli::Base
     end
   end
 
+  desc "broadcast", "Broadcast an audit message"
+  option :message, aliases: "-m", type: :string, desc: "Audit mesasge", required: true
+  def broadcast
+    say "Broadcast: #{options[:message]}", :magenta
+    audit_broadcast options[:message]
+  end
+
   desc "version", "Show MRSK version"
   def version
     puts Mrsk::VERSION

lib/mrsk/commander.rb

@@ -84,8 +84,8 @@ class Mrsk::Commander
     Mrsk::Commands::Accessory.new(config, name: name)
   end
 
-  def auditor(role: nil)
+  def auditor(**details)
-    Mrsk::Commands::Auditor.new(config, role: role)
+    Mrsk::Commands::Auditor.new(config, **details)
   end
 
   def builder

lib/mrsk/commands/auditor.rb

@@ -1,36 +1,27 @@
-require "active_support/core_ext/time/conversions"
+require "time"
 
 class Mrsk::Commands::Auditor < Mrsk::Commands::Base
-  attr_reader :role
+  attr_reader :details
 
-  def initialize(config, role: nil)
+  def initialize(config, **details)
     super(config)
-    @role = role
+    @details = default_details.merge(details)
   end
 
   # Runs remotely
-  def record(line)
+  def record(line, **details)
     append \
-      [ :echo, tagged_record_line(line) ],
+      [ :echo, *audit_tags(**details), line ],
       audit_log_file
   end
 
   # Runs locally
-  def broadcast(line)
+  def broadcast(line, **details)
     if broadcast_cmd = config.audit_broadcast_cmd
-      [ broadcast_cmd, tagged_broadcast_line(line) ]
+      [ broadcast_cmd, *broadcast_args(line, **details), env: env_for(event: line, **details) ]
     end
   end
 
-  def broadcast_environment(line)
-    {
-      "MRSK_PERFORMER" => performer,
-      "MRSK_ROLE" => role,
-      "MRSK_DESTINATION" => config.destination,
-      "MRSK_MESSAGE" => line
-    }
-  end
-
   def reveal
     [ :tail, "-n", 50, audit_log_file ]
   end
@@ -40,35 +31,29 @@ class Mrsk::Commands::Auditor < Mrsk::Commands::Base
       [ "mrsk", config.service, config.destination, "audit.log" ].compact.join("-")
     end
 
-    def tagged_record_line(line)
+    def default_details
-      tagged_line recorded_at_tag, performer_tag, role_tag, line
+      { recorded_at: Time.now.utc.iso8601,
+        performer: `whoami`.chomp,
+        destination: config.destination }
     end
 
-    def tagged_broadcast_line(line)
+    def audit_tags(**details)
-      tagged_line performer_tag, role_tag, destination_tag, line
+      tags_for **self.details.merge(details)
     end
 
-    def tagged_line(*tags_and_line)
+    def broadcast_args(line, **details)
-      "'#{tags_and_line.compact.join(" ")}'"
+      "'#{broadcast_tags(**details).join(" ")} #{line}'"
     end
 
-    def recorded_at_tag
+    def broadcast_tags(**details)
-      "[#{Time.now.to_fs(:db)}]"
+      tags_for **self.details.merge(details).except(:recorded_at)
     end
 
-    def performer
+    def tags_for(**details)
-      `whoami`.strip
+      details.compact.values.map { |value| "[#{value}]" }
     end
 
-    def performer_tag
+    def env_for(**details)
-      "[#{performer}]"
+      self.details.merge(details).compact.transform_keys { |detail| "MRSK_#{detail.upcase}" }
-    end
-
-    def role_tag
-      "[#{role}]" if role
-    end
-
-    def destination_tag
-      "[#{config.destination}]" if config.destination
     end
 end

lib/mrsk/commands/lock.rb

@@ -1,5 +1,5 @@
 require "active_support/duration"
-require "active_support/core_ext/numeric/time"
+require "time"
 
 class Mrsk::Commands::Lock < Mrsk::Commands::Base
   def acquire(message, version)
@@ -49,7 +49,7 @@ class Mrsk::Commands::Lock < Mrsk::Commands::Base
 
     def lock_details(message, version)
       <<~DETAILS.strip
-        Locked by: #{locked_by} at #{Time.now.gmtime}
+        Locked by: #{locked_by} at #{Time.now.utc.iso8601}
         Version: #{version}
         Message: #{message}
       DETAILS

lib/mrsk/sshkit_with_ext.rb

@@ -1,5 +1,6 @@
 require "sshkit"
 require "sshkit/dsl"
+require "active_support/core_ext/hash/deep_merge"
 
 class SSHKit::Backend::Abstract
   def capture_with_info(*args, **kwargs)
@@ -9,4 +10,36 @@ class SSHKit::Backend::Abstract
   def puts_by_host(host, output, type: "App")
     puts "#{type} Host: #{host}\n#{output}\n\n"
   end
+
+  # Our execution pattern is for the CLI execute args lists returned
+  # from commands, but this doesn't support returning execution options
+  # from the command.
+  #
+  # Support this by using kwargs for CLI options and merging with the
+  # args-extracted options.
+  module CommandEnvMerge
+    private
+
+    # Override to merge options returned by commands in the args list with
+    # options passed by the CLI and pass them along as kwargs.
+    def command(*args_and_options)
+      options, args = args_and_options.partition { |a| a.is_a? Hash }
+      build_command(*args, **options.reduce(:deep_merge))
+    end
+
+    # Destructure options to pluck out env for merge
+    def build_command(args, env: nil, **options)
+      # Rely on native Ruby kwargs precedence rather than explicit Hash merges
+      SSHKit::Command.new(*args, **default_command_options, **options, env: env_for(env))
+    end
+
+    def default_command_options
+      { in: pwd_path, host: @host, user: @user, group: @group }
+    end
+
+    def env_for(env)
+      @env.to_h.merge(env.to_h)
+    end
+  end
+  prepend CommandEnvMerge
 end

test/cli/main_test.rb

@@ -321,6 +321,19 @@ class CliMainTest < CliTestCase
     end
   end
 
+  test "broadcast" do
+    SSHKit::Backend::Abstract.any_instance.expects(:execute).with do |command, line, options, verbosity:|
+      command == "bin/audit_broadcast" &&
+        line =~ /\A'\[[^\]]+\] message'\z/ &&
+        options[:env].keys == %w[ MRSK_RECORDED_AT MRSK_PERFORMER MRSK_EVENT ] &&
+        verbosity == :debug
+    end.returns("Broadcast audit message: message")
+
+    run_command("broadcast", "-m", "message").tap do |output|
+      assert_match "Broadcast: message", output
+    end
+  end
+
   test "version" do
     version = stdouted { Mrsk::Cli::Main.new.version }
     assert_equal Mrsk::VERSION, version

test/commands/auditor_test.rb

@@ -6,55 +6,65 @@ class CommandsAuditorTest < ActiveSupport::TestCase
       service: "app", image: "dhh/app", registry: { "username" => "dhh", "password" => "secret" }, servers: [ "1.1.1.1" ],
       audit_broadcast_cmd: "bin/audit_broadcast"
     }
+
+    @auditor = new_command
   end
 
   test "record" do
-    assert_match \
+    assert_equal [
-      /echo '.* app removed container' >> mrsk-app-audit.log/,
+      :echo,
-      new_command.record("app removed container").join(" ")
+      "[#{@auditor.details[:recorded_at]}]", "[#{@auditor.details[:performer]}]",
+      "app removed container",
+      ">>", "mrsk-app-audit.log"
+    ], @auditor.record("app removed container")
   end
 
   test "record with destination" do
-    @destination = "staging"
+    new_command(destination: "staging").tap do |auditor|
-
+      assert_equal [
-    assert_match \
+        :echo,
-      /echo '.* app removed container' >> mrsk-app-staging-audit.log/,
+        "[#{auditor.details[:recorded_at]}]", "[#{auditor.details[:performer]}]", "[#{auditor.details[:destination]}]",
-      new_command.record("app removed container").join(" ")
+        "app removed container",
+        ">>", "mrsk-app-staging-audit.log"
+      ], auditor.record("app removed container")
+    end
   end
 
-  test "record with role" do
+  test "record with command details" do
-    @role = "web"
+    new_command(role: "web").tap do |auditor|
+      assert_equal [
+        :echo,
+        "[#{auditor.details[:recorded_at]}]", "[#{auditor.details[:performer]}]", "[#{auditor.details[:role]}]",
+        "app removed container",
+        ">>", "mrsk-app-audit.log"
+      ], auditor.record("app removed container")
+    end
+  end
 
-    assert_match \
+  test "record with arg details" do
-      /echo '.* \[web\] app removed container' >> mrsk-app-audit.log/,
+    assert_equal [
-      new_command.record("app removed container").join(" ")
+      :echo,
+      "[#{@auditor.details[:recorded_at]}]", "[#{@auditor.details[:performer]}]", "[value]",
+      "app removed container",
+      ">>", "mrsk-app-audit.log"
+    ], @auditor.record("app removed container", detail: "value")
   end
 
   test "broadcast" do
-    Mrsk::Commands::Auditor.any_instance.stubs(:performer).returns("bob")
+    assert_equal [
-    @role = "web"
+      "bin/audit_broadcast",
-    @destination = "staging"
+      "'[#{@auditor.details[:performer]}] [value] app removed container'",
-
+      env: {
-    assert_equal \
+        "MRSK_RECORDED_AT" => @auditor.details[:recorded_at],
-      ["bin/audit_broadcast", "'[bob] [web] [staging] app removed container'"],
+        "MRSK_PERFORMER" => @auditor.details[:performer],
-      new_command.broadcast("app removed container")
+        "MRSK_EVENT" => "app removed container",
-  end
+        "MRSK_DETAIL" => "value"
-
+      }
-  test "broadcast environment" do
+    ], @auditor.broadcast("app removed container", detail: "value")
-    Mrsk::Commands::Auditor.any_instance.stubs(:performer).returns("bob")
-    @role = "web"
-    @destination = "staging"
-
-    env = new_command.broadcast_environment("app removed container")
-
-    assert_equal "bob", env["MRSK_PERFORMER"]
-    assert_equal "web", env["MRSK_ROLE"]
-    assert_equal "staging", env["MRSK_DESTINATION"]
-    assert_equal "app removed container", env["MRSK_MESSAGE"]
   end
 
   private
-    def new_command
+    def new_command(destination: nil, **details)
-      Mrsk::Commands::Auditor.new(Mrsk::Configuration.new(@config, destination: @destination, version: "123"), role: @role)
+      Mrsk::Commands::Auditor.new(Mrsk::Configuration.new(@config, destination: destination, version: "123"), **details)
     end
 end

test/fixtures/deploy_simple.yml

@@ -6,3 +6,4 @@ servers:
 registry:
   username: user
   password: pw
+audit_broadcast_cmd: "bin/audit_broadcast"