Bump version for 0.12.1

Allow customizing audit broadcast with env

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    mrsk (0.12.0)
+    mrsk (0.12.1)
       activesupport (>= 7.0)
       bcrypt_pbkdf (~> 1.0)
       dotenv (~> 2.8)

README.md

@@ -308,7 +308,7 @@ You can specialize the default Traefik rules by setting labels on the containers
 labels:
   traefik.http.routers.hey-web.rule: Host(`app.hey.com`)
 ```
-Traefik rules are in the "service-role-destination" format. The default role will be `web` if no rule is specified. If the destination is not specified, it is not included. To give an example, the above rule would become "traefik.http.routers.hey-web.rule" if it was for the "staging" destination.
+Traefik rules are in the "service-role-destination" format. The default role will be `web` if no rule is specified. If the destination is not specified, it is not included. To give an example, the above rule would become "traefik.http.routers.hey-web-staging.rule" if it was for the "staging" destination.
 
 Note: The backticks are needed to ensure the rule is passed in correctly and not treated as command substitution by Bash!
 
@@ -677,6 +677,21 @@ That'll post a line like follows to a preconfigured chatbot in Basecamp:
 [My App] [dhh] Rolled back to version d264c4e92470ad1bd18590f04466787262f605de
 ```
 
+`MRSK_*` environment variables are available to the broadcast command for
+fine-grained audit reporting, e.g. for triggering deployment reports or
+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"
+
+Use `mrsk broadcast` to test and troubleshoot your broadcast command:
+
+```bash
+mrsk broadcast -m "test audit message"
+```
+
 ### Healthcheck
 
 MRSK uses Docker healtchecks to check the health of your application during deployment. Traefik uses this same healthcheck status to determine when a container is ready to receive traffic.
@@ -714,7 +729,7 @@ servers:
 
 The healthcheck allows for an optional `max_attempts` setting, which will attempt the healthcheck up to the specified number of times before failing the deploy. This is useful for applications that take a while to start up. The default is 7.
 
-Note that the HTTP health checks assume that the `curl` command is avilable inside the container. If that's not the case, use the healthcheck's `cmd` option to specify an alternative check that the container supports.
+Note: The HTTP health checks assume that the `curl` command is available inside the container. If that's not the case, use the healthcheck's `cmd` option to specify an alternative check that the container supports.
 
 ## Commands
 

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/healthcheck.rb

@@ -9,6 +9,7 @@ class Mrsk::Cli::Healthcheck < Mrsk::Cli::Base
         Mrsk::Utils::HealthcheckPoller.wait_for_healthy { capture_with_info(*MRSK.healthcheck.status) }
       rescue Mrsk::Utils::HealthcheckPoller::HealthcheckError => e
         error capture_with_info(*MRSK.healthcheck.logs)
+        error capture_with_pretty_json(*MRSK.healthcheck.container_health_log)
         raise
       ensure
         execute *MRSK.healthcheck.stop, raise_on_non_zero_exit: false

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)
-    Mrsk::Commands::Auditor.new(config, role: role)
+  def auditor(**details)
+    Mrsk::Commands::Auditor.new(config, **details)
   end
 
   def builder

lib/mrsk/commands/auditor.rb

@@ -1,24 +1,24 @@
-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
 
@@ -31,27 +31,29 @@ class Mrsk::Commands::Auditor < Mrsk::Commands::Base
       [ "mrsk", config.service, config.destination, "audit.log" ].compact.join("-")
     end
 
-    def tagged_record_line(line)
-      tagged_line recorded_at_tag, performer_tag, role_tag, line
+    def default_details
+      { recorded_at: Time.now.utc.iso8601,
+        performer: `whoami`.chomp,
+        destination: config.destination }
     end
 
-    def tagged_broadcast_line(line)
-      tagged_line performer_tag, role_tag, line
+    def audit_tags(**details)
+      tags_for **self.details.merge(details)
     end
 
-    def tagged_line(*tags_and_line)
-      "'#{tags_and_line.compact.join(" ")}'"
+    def broadcast_args(line, **details)
+      "'#{broadcast_tags(**details).join(" ")} #{line}'"
     end
 
-    def recorded_at_tag
-      "[#{Time.now.to_fs(:db)}]"
+    def broadcast_tags(**details)
+      tags_for **self.details.merge(details).except(:recorded_at)
     end
 
-    def performer_tag
-      "[#{`whoami`.strip}]"
+    def tags_for(**details)
+      details.compact.values.map { |value| "[#{value}]" }
     end
 
-    def role_tag
-      "[#{role}]" if role
+    def env_for(**details)
+      self.details.merge(details).compact.transform_keys { |detail| "MRSK_#{detail.upcase}" }
     end
 end

lib/mrsk/commands/base.rb

@@ -3,6 +3,7 @@ module Mrsk::Commands
     delegate :sensitive, :argumentize, to: Mrsk::Utils
 
     DOCKER_HEALTH_STATUS_FORMAT = "'{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}'"
+    DOCKER_HEALTH_LOG_FORMAT    = "'{{json .State.Health}}'"
 
     attr_accessor :config
 

lib/mrsk/commands/healthcheck.rb

@@ -22,6 +22,10 @@ class Mrsk::Commands::Healthcheck < Mrsk::Commands::Base
     pipe container_id, xargs(docker(:inspect, "--format", DOCKER_HEALTH_STATUS_FORMAT))
   end
 
+  def container_health_log
+    pipe container_id, xargs(docker(:inspect, "--format", DOCKER_HEALTH_LOG_FORMAT))
+  end
+
   def logs
     pipe container_id, xargs(docker(:logs, "--tail", 50, "2>&1"))
   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/commands/prune.rb

@@ -3,7 +3,7 @@ require "active_support/core_ext/numeric/time"
 
 class Mrsk::Commands::Prune < Mrsk::Commands::Base
   def images
-    docker :image, :prune, "--all", "--force", "--filter", "label=service=#{config.service}", "--filter", "dangling=true"
+    docker :image, :prune, "--force", "--filter", "label=service=#{config.service}", "--filter", "dangling=true"
   end
 
   def containers(keep_last: 5)

lib/mrsk/sshkit_with_ext.rb

@@ -1,12 +1,52 @@
 require "sshkit"
 require "sshkit/dsl"
+require "active_support/core_ext/hash/deep_merge"
+require "json"
 
 class SSHKit::Backend::Abstract
   def capture_with_info(*args, **kwargs)
     capture(*args, **kwargs, verbosity: Logger::INFO)
   end
 
+  def capture_with_pretty_json(*args, **kwargs)
+    JSON.pretty_generate(JSON.parse(capture(*args, **kwargs)))
+  end
+
   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, options)
+      more_options, args = args.partition { |a| a.is_a? Hash }
+      more_options << options
+
+      build_command(args, **more_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

lib/mrsk/version.rb

@@ -1,3 +1,3 @@
 module Mrsk
-  VERSION = "0.12.0"
+  VERSION = "0.12.1"
 end

test/cli/healthcheck_test.rb

@@ -53,6 +53,11 @@ class CliHealthcheckTest < CliTestCase
       .with(:docker, :container, :ls, "--all", "--filter", "name=^healthcheck-app-999$", "--quiet", "|", :xargs, :docker, :logs, "--tail", 50, "2>&1")
       .returns("some log output")
 
+    # Capture container health log when failing
+    SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_pretty_json)
+      .with(:docker, :container, :ls, "--all", "--filter", "name=^healthcheck-app-999$", "--quiet", "|", :xargs, :docker, :inspect, "--format",  "'{{json .State.Health}}'")
+      .returns('{"Status":"unhealthy","Log":[{"ExitCode": 1,"Output": "/bin/sh: 1: curl: not found\n"}]}"')
+
     exception = assert_raises do
       run_command("perform")
     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/cli/prune_test.rb

@@ -10,7 +10,7 @@ class CliPruneTest < CliTestCase
 
   test "images" do
     run_command("images").tap do |output|
-      assert_match /docker image prune --all --force --filter label=service=app --filter dangling=true on 1.1.1.\d/, output
+      assert_match /docker image prune --force --filter label=service=app --filter dangling=true on 1.1.1.\d/, output
     end
   end
 

test/commands/auditor_test.rb

@@ -6,38 +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 \
-      /echo '.* app removed container' >> mrsk-app-audit.log/,
-      new_command.record("app removed container").join(" ")
+    assert_equal [
+      :echo,
+      "[#{@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"
-
-    assert_match \
-      /echo '.* app removed container' >> mrsk-app-staging-audit.log/,
-      new_command.record("app removed container").join(" ")
+    new_command(destination: "staging").tap do |auditor|
+      assert_equal [
+        :echo,
+        "[#{auditor.details[:recorded_at]}]", "[#{auditor.details[:performer]}]", "[#{auditor.details[:destination]}]",
+        "app removed container",
+        ">>", "mrsk-app-staging-audit.log"
+      ], auditor.record("app removed container")
+    end
   end
 
-  test "record with role" do
-    @role = "web"
+  test "record with command details" do
+    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 \
-      /echo '.* \[web\] app removed container' >> mrsk-app-audit.log/,
-      new_command.record("app removed container").join(" ")
+  test "record with arg details" do
+    assert_equal [
+      :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
-    assert_match \
-      /bin\/audit_broadcast '\[.*\] app removed container'/,
-      new_command.broadcast("app removed container").join(" ")
+    assert_equal [
+      "bin/audit_broadcast",
+      "'[#{@auditor.details[:performer]}] [value] app removed container'",
+      env: {
+        "MRSK_RECORDED_AT" => @auditor.details[:recorded_at],
+        "MRSK_PERFORMER" => @auditor.details[:performer],
+        "MRSK_EVENT" => "app removed container",
+        "MRSK_DETAIL" => "value"
+      }
+    ], @auditor.broadcast("app removed container", detail: "value")
   end
 
   private
-    def new_command
-      Mrsk::Commands::Auditor.new(Mrsk::Configuration.new(@config, destination: @destination, version: "123"), role: @role)
+    def new_command(destination: nil, **details)
+      Mrsk::Commands::Auditor.new(Mrsk::Configuration.new(@config, destination: destination, version: "123"), **details)
     end
 end

test/commands/healthcheck_test.rb

@@ -51,6 +51,12 @@ class CommandsHealthcheckTest < ActiveSupport::TestCase
       new_command.status.join(" ")
   end
 
+  test "container_health_log" do
+    assert_equal \
+      "docker container ls --all --filter name=^healthcheck-app-123$ --quiet | xargs docker inspect --format '{{json .State.Health}}'",
+      new_command.container_health_log.join(" ")
+  end
+
   test "stop" do
     assert_equal \
       "docker container ls --all --filter name=^healthcheck-app-123$ --quiet | xargs docker stop",

test/commands/prune_test.rb

@@ -10,7 +10,7 @@ class CommandsPruneTest < ActiveSupport::TestCase
 
   test "images" do
     assert_equal \
-      "docker image prune --all --force --filter label=service=app --filter dangling=true",
+      "docker image prune --force --filter label=service=app --filter dangling=true",
       new_command.images.join(" ")
   end
 

test/fixtures/deploy_simple.yml

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

test/integration/deploy_test.rb

@@ -13,11 +13,36 @@ class DeployTest < ActiveSupport::TestCase
   end
 
   test "deploy" do
+    first_version = latest_app_version
+
     assert_app_is_down
 
     mrsk :deploy
 
-    assert_app_is_up
+    assert_app_is_up version: first_version
+
+    second_version = update_app_rev
+
+    mrsk :redeploy
+
+    assert_app_is_up version: second_version
+
+    mrsk :rollback, first_version
+
+    assert_app_is_up version: first_version
+
+    details = mrsk :details, capture: true
+
+    assert_match /Traefik Host: vm1/, details
+    assert_match /Traefik Host: vm2/, details
+    assert_match /App Host: vm1/, details
+    assert_match /App Host: vm2/, details
+    assert_match /traefik:v2.9/, details
+    assert_match /registry:4443\/app:#{first_version}/, details
+
+    audit = mrsk :audit, capture: true
+
+    assert_match /Booted app version #{first_version}.*Booted app version #{second_version}.*Booted app version #{first_version}.*/m, audit
   end
 
   private
@@ -34,23 +59,19 @@ class DeployTest < ActiveSupport::TestCase
       result
     end
 
-    def deployer_exec(*commands, capture: false)
-      if capture
-        stdouted { docker_compose("exec deployer #{commands.join(" ")}") }
-      else
-        docker_compose("exec deployer #{commands.join(" ")}", capture: capture)
-      end
+    def deployer_exec(*commands, **options)
+      docker_compose("exec deployer #{commands.join(" ")}", **options)
     end
 
-    def mrsk(*commands, capture: false)
-      deployer_exec(:mrsk, *commands, capture: capture)
+    def mrsk(*commands, **options)
+      deployer_exec(:mrsk, *commands, **options)
     end
 
     def assert_app_is_down
       assert_equal "502", app_response.code
     end
 
-    def assert_app_is_up
+    def assert_app_is_up(version: nil)
       code = app_response.code
       if code != "200"
         puts "Got response code #{code}, here are the traefik logs:"
@@ -60,12 +81,44 @@ class DeployTest < ActiveSupport::TestCase
         puts "Tried to get the response code again and got #{app_response.code}"
       end
       assert_equal "200", code
+      assert_app_version(version) if version
+    end
+
+    def assert_app_not_found
+      assert_equal "404", app_response.code
+    end
+
+    def wait_for_app_to_be_up(timeout: 10, up_count: 3)
+      timeout_at = Time.now + timeout
+      up_times = 0
+      response = app_response
+      while up_times < up_count && timeout_at > Time.now
+        sleep 0.1
+        up_times += 1 if response.code == "200"
+        response = app_response
+      end
+      assert_equal up_times, up_count
     end
 
     def app_response
       Net::HTTP.get_response(URI.parse("http://localhost:12345"))
     end
 
+    def update_app_rev
+      deployer_exec "./update_app_rev.sh"
+      latest_app_version
+    end
+
+    def latest_app_version
+      deployer_exec("cat version", capture: true)
+    end
+
+    def assert_app_version(version)
+      actual_version = Net::HTTP.get_response(URI.parse("http://localhost:12345/version")).body.strip
+
+      assert_equal version, actual_version
+    end
+
     def wait_for_healthy(timeout: 20)
       timeout_at = Time.now + timeout
       while docker_compose("ps -a | tail -n +2 | grep -v '(healthy)' | wc -l", capture: true) != "0"

test/integration/docker/deployer/Dockerfile

@@ -14,7 +14,7 @@ RUN echo \
 
 RUN apt-get update --fix-missing && apt-get install -y docker-ce docker-ce-cli containerd.io docker-buildx-plugin docker-compose-plugin
 
-COPY boot.sh .
+COPY *.sh .
 COPY app/ .
 
 RUN ln -s /shared/ssh /root/.ssh
@@ -23,6 +23,7 @@ RUN mkdir -p /etc/docker/certs.d/registry:4443 && ln -s /shared/certs/domain.crt
 RUN git config --global user.email "deployer@example.com"
 RUN git config --global user.name "Deployer"
 RUN git init && git add . && git commit -am "Initial version"
+RUN git rev-parse HEAD > version
 
 HEALTHCHECK --interval=1s CMD pgrep sleep
 

test/integration/docker/deployer/app/Dockerfile

@@ -1,3 +1,4 @@
 FROM nginx:1-alpine-slim
 
 COPY default.conf /etc/nginx/conf.d/default.conf
+COPY version /usr/share/nginx/html/version

test/integration/docker/deployer/update_app_rev.sh

@@ -0,0 +1,4 @@
+#!/bin/bash
+
+git commit -am 'Update rev' --amend
+git rev-parse HEAD > version