Rework deploy output

lib/kubernetes-deploy/deferred_summary_logging.rb

@@ -0,0 +1,92 @@
+module KubernetesDeploy
+  # Adds the methods kubernetes-deploy requires to your logger class.
+  # These methods include helpers for logging consistent headings, as well as facilities for
+  # displaying key information later, in a summary section, rather than when it occurred.
+  module DeferredSummaryLogging
+    attr_reader :summary
+    def initialize(*args)
+      reset
+      super
+    end
+
+    def reset
+      @summary = DeferredSummary.new
+      @current_phase = 0
+    end
+
+    def blank_line(level = :info)
+      public_send(level, "")
+    end
+
+    def phase_heading(phase_name)
+      @current_phase += 1
+      heading("Phase #{@current_phase}: #{phase_name}")
+    end
+
+    def heading(text, secondary_msg='', secondary_msg_color=:blue)
+      padding = (100.0 - (text.length + secondary_msg.length)) / 2
+      blank_line
+      part1 = ColorizedString.new("#{'-' * padding.floor}#{text}").blue
+      part2 = ColorizedString.new(secondary_msg).colorize(secondary_msg_color)
+      part3 = ColorizedString.new("#{'-' * padding.ceil}").blue
+      info(part1 + part2 + part3)
+    end
+
+    # Outputs the deferred summary information saved via @logger.summary.add_action and @logger.summary.add_paragraph
+    def print_summary(success)
+      if success
+        heading("Result: ", "SUCCESS", :green)
+        level = :info
+      else
+        heading("Result: ", "FAILURE", :red)
+        level = :fatal
+      end
+
+      public_send(level, summary.actions_sentence)
+      summary.paragraphs.each do |para|
+        blank_line(level)
+        msg_lines = para.split("\n")
+        msg_lines.each { |line| public_send(level, line) }
+      end
+    end
+
+    class DeferredSummary
+      attr_reader :paragraphs, :actions_taken
+      attr_accessor :failure_reason
+
+      def initialize
+        @actions_taken = []
+        @paragraphs = []
+        @failure_reason = ""
+      end
+
+      def actions_sentence
+        sent = case actions_taken.length
+        when 0 then "No actions taken"
+        when 1 then actions_taken.first
+        when 2 then actions_taken.join(" and ")
+        else
+          actions_taken[0..-2].join(", ") + " and " + actions_taken[-1]
+        end
+        sent.capitalize
+      end
+
+      # Saves a sentence fragment to be displayed in the first sentence of the summary section
+      #
+      # Example:
+      # # The resulting summary will begin with "Created 3 secrets and failed to deploy 2 resources"
+      # @logger.summary.add_action("created 3 secrets")
+      # @logger.summary.add_cation("failed to deploy 2 resources")
+      def add_action(sentence_fragment)
+        @actions_taken << sentence_fragment
+      end
+
+      # Adds a paragraph to be displayed in the summary section
+      # Paragraphs will be printed in the order they were added, separated by a blank line
+      # This can be used to log a block of data on a particular topic, e.g. debug info for a particular failed resource
+      def add_paragraph(paragraph)
+        paragraphs << paragraph
+      end
+    end
+  end
+end

lib/kubernetes-deploy/ejson_secret_provisioner.rb

@@ -49,23 +49,27 @@ def create_secrets
           validate_secret_spec(secret_name, secret_spec)
           create_or_update_secret(secret_name, secret_spec["_type"], secret_spec["data"])
         end
+        @logger.summary.add_action("created/updated #{secrets.length} #{'secret'.pluralize(secrets.length)}")
       end
     end
 
     def prune_managed_secrets
       ejson_secret_names = encrypted_ejson.fetch(MANAGED_SECRET_EJSON_KEY, {}).keys
       live_secrets = run_kubectl_json("get", "secrets")
 
+      prune_count = 0
       live_secrets.each do |secret|
         secret_name = secret["metadata"]["name"]
         next unless secret_managed?(secret)
         next if ejson_secret_names.include?(secret_name)
 
         @logger.info("Pruning secret #{secret_name}")
+        prune_count += 1
         out, err, st = @kubectl.run("delete", "secret", secret_name)
         @logger.debug(out)
         raise EjsonSecretError, err unless st.success?
       end
+      @logger.summary.add_action("pruned #{prune_count} #{'secret'.pluralize(prune_count)}") if prune_count > 0
     end
 
     def managed_secrets_exist?

lib/kubernetes-deploy/formatted_logger.rb

@@ -1,8 +1,11 @@
 # frozen_string_literal: true
 require 'logger'
+require 'kubernetes-deploy/deferred_summary_logging'
 
 module KubernetesDeploy
   class FormattedLogger < Logger
+    include DeferredSummaryLogging
+
     def self.build(namespace, context, stream = $stderr, verbose_prefix: false)
       l = new(stream)
       l.level = level_from_env
@@ -13,11 +16,11 @@ def self.build(namespace, context, stream = $stderr, verbose_prefix: false)
 
         case severity
         when "FATAL"
+          ColorizedString.new("[#{severity}][#{datetime}]#{middle}\t").red + "#{msg}\n"
+        when "ERROR"
           colorized_line.red
-        when "ERROR", "WARN"
+        when "WARN"
           colorized_line.yellow
-        when "INFO"
-          msg =~ /^\[(KUBESTATUS|Pod)/ ? colorized_line : colorized_line.blue
         else
           colorized_line
         end
@@ -35,9 +38,5 @@ def self.level_from_env
       end
     end
     private_class_method :level_from_env
-
-    def blank_line(level = :info)
-      public_send(level, "")
-    end
   end
 end

lib/kubernetes-deploy/kubernetes_resource.rb

@@ -1,3 +1,4 @@
+# frozen_string_literal: true
 require 'json'
 require 'open3'
 require 'shellwords'
@@ -10,6 +11,16 @@ class KubernetesResource
 
     TIMEOUT = 5.minutes
 
+    DEBUG_RESOURCE_NOT_FOUND_MESSAGE = "None found. Please check your usual logging service (e.g. Splunk)."
+    UNUSUAL_FAILURE_MESSAGE = <<-MSG.strip_heredoc.strip
+      It is very unusual for this resource type to fail to deploy. Please try the deploy again.
+      If that new deploy also fails, contact your cluster administrator.
+      MSG
+    STANDARD_TIMEOUT_MESSAGE = <<-MSG.strip_heredoc.strip
+      Kubernetes will continue to attempt to deploy this resource in the cluster, but at this point it is considered unlikely that it will succeed.
+      If you have reason to believe it will succeed, retry the deploy to continue to monitor the rollout.
+      MSG
+
     def self.for_type(type:, name:, namespace:, context:, file:, logger:)
       subclass = case type
       when 'cloudsql' then Cloudsql
@@ -56,7 +67,6 @@ def id
     end
 
     def sync
-      log_status
     end
 
     def deploy_failed?
@@ -77,7 +87,6 @@ def exists?
 
     def status
       @status ||= "Unknown"
-      deploy_timed_out? ? "Timed out with status #{@status}" : @status
     end
 
     def type
@@ -103,24 +112,84 @@ def deploy_method
       tpr? ? :replace : :apply
     end
 
-    def status_data
-      {
-        group: group_name,
-        name: name,
-        status_string: status,
-        exists: exists?,
-        succeeded: deploy_succeeded?,
-        failed: deploy_failed?,
-        timed_out: deploy_timed_out?
-      }
+    def debug_message
+      helpful_info = []
+      if deploy_failed?
+        helpful_info << ColorizedString.new("#{id}: FAILED").red
+        helpful_info << failure_message if failure_message.present?
+      else
+        helpful_info << "#{ColorizedString.new("#{id }: TIMED OUT").yellow} (limit: #{timeout}s)"
+        helpful_info << timeout_message if timeout_message.present?
+      end
+      helpful_info << "  - Final status: #{status}"
+
+      events = get_events
+      if events.present?
+        helpful_info << "  - Events:"
+        events.each do |identifier, event_hashes|
+          event_hashes.each { |event| helpful_info << "      [#{identifier}]\t#{event.to_json}" }
+        end
+      else
+        helpful_info << "  - Events: #{DEBUG_RESOURCE_NOT_FOUND_MESSAGE}"
+      end
+
+      if respond_to?(:get_logs)
+        container_logs = get_logs
+        if container_logs.blank? || container_logs.values.all?(&:blank?)
+          helpful_info << "  - Logs: #{DEBUG_RESOURCE_NOT_FOUND_MESSAGE}"
+        else
+          helpful_info << "  - Logs:"
+          container_logs.each do |identifier, logs|
+            logs.split("\n").each do |line|
+              helpful_info << "      [#{identifier}]\t#{line}"
+            end
+          end
+        end
+      end
+
+      helpful_info.join("\n")
+    end
+
+    # Returns a hash in the following format:
+    # {
+    #   "pod/web-1" => [
+    #     {"subject_kind" => "Pod", "some" => "stuff"}, # event 1
+    #     {"subject_kind" => "Pod", "other" => "stuff"}, # event 2
+    #   ]
+    # }
+    def get_events
+      return {} unless exists?
+      out, _err, st = kubectl.run("get", "events", %(--output=jsonpath={range .items[?(@.involvedObject.name=="#{name}")]}{.involvedObject.kind}\t{.count}\t{.message}\t{.reason}\t{.type}\n{end}))
+      return {} unless st.success?
+
+      events = Hash.new { |hash, key| hash[key] = [] }
+      out.split("\n").each_with_object(events) do |event_blob, events|
+        pieces = event_blob.split("\t")
+        event = {
+          "subject_kind" => pieces[0],
+          "count" => pieces[1],
+          "message" => pieces[2],
+          "reason" => pieces[3],
+          "type" => pieces[4]
+        }
+        # jsonpath can only filter by one thing at a time, and we chose involvedObject.name
+        # This means we still need to filter by involvedObject.kind here to make sure we only retain relevant events
+        next unless event["subject_kind"].downcase == type.downcase
+        events[id] << event
+      end
+    end
+
+    def timeout_message
+      STANDARD_TIMEOUT_MESSAGE
     end
 
-    def group_name
-      type.downcase.pluralize
+    def failure_message
     end
 
-    def log_status
-      @logger.info("[KUBESTATUS] #{JSON.dump(status_data)}")
+    def pretty_status
+      padding = " " * (50 - id.length)
+      msg = exists? ? status : "not found"
+      "#{id}#{padding}#{msg}"
     end
 
     def kubectl

lib/kubernetes-deploy/kubernetes_resource/bugsnag.rb

@@ -12,7 +12,6 @@ def sync
         @secret_found = secrets.split.any? { |s| s.end_with?("-bugsnag") }
       end
       @status = @secret_found ? "Available" : "Unknown"
-      log_status
     end
 
     def deploy_succeeded?

lib/kubernetes-deploy/kubernetes_resource/cloudsql.rb

@@ -6,17 +6,17 @@ class Cloudsql < KubernetesResource
     def sync
       _, _err, st = kubectl.run("get", type, @name)
       @found = st.success?
-      @status = if cloudsql_proxy_deployment_exists? && mysql_service_exists?
+      @deployment_exists = cloudsql_proxy_deployment_exists?
+      @service_exists = mysql_service_exists?
+      @status = if @deployment_exists && @service_exists
         "Provisioned"
       else
         "Unknown"
       end
-
-      log_status
     end
 
     def deploy_succeeded?
-      cloudsql_proxy_deployment_exists? && mysql_service_exists?
+      @service_exists && @deployment_exists
     end
 
     def deploy_failed?

lib/kubernetes-deploy/kubernetes_resource/config_map.rb

@@ -7,7 +7,6 @@ def sync
       _, _err, st = kubectl.run("get", type, @name)
       @status = st.success? ? "Available" : "Unknown"
       @found = st.success?
-      log_status
     end
 
     def deploy_succeeded?
@@ -18,6 +17,10 @@ def deploy_failed?
       false
     end
 
+    def timeout_message
+      UNUSUAL_FAILURE_MESSAGE
+    end
+
     def exists?
       @found
     end

lib/kubernetes-deploy/kubernetes_resource/deployment.rb

@@ -8,12 +8,13 @@ def sync
       @found = st.success?
       @rollout_data = {}
       @status = nil
+      @representative_pod = nil
       @pods = []
 
       if @found
         @rollout_data = JSON.parse(json_data)["status"]
           .slice("updatedReplicas", "replicas", "availableReplicas", "unavailableReplicas")
-        @status, _err, _ = kubectl.run("rollout", "status", type, @name, "--watch=false") if @deploy_started
+        @status = @rollout_data.map { |st, num| "#{num} #{st}" }.join(", ")
 
         pod_list, _err, st = kubectl.run("get", "pods", "-a", "-l", "name=#{name}", "--output=json")
         if st.success?
@@ -30,12 +31,24 @@ def sync
             )
             pod.deploy_started = @deploy_started
             pod.interpret_json_data(pod_json)
+
+            if !@representative_pod && pod_probably_new?(pod_json)
+              @representative_pod = pod
+            end
             @pods << pod
           end
         end
       end
+    end
 
-      log_status
+    def get_logs
+      @representative_pod ? @representative_pod.get_logs : {}
+    end
+
+    def get_events
+      own_events = super
+      return own_events unless @representative_pod
+      own_events.merge(@representative_pod.get_events)
     end
 
     def deploy_succeeded?
@@ -59,8 +72,12 @@ def exists?
       @found
     end
 
-    def status_data
-      super.merge(replicas: @rollout_data, num_pods: @pods.length)
+    private
+
+    def pod_probably_new?(pod_json)
+      return false unless @deploy_started
+      # Shitty, brittle workaround to identify a pod from the new ReplicaSet before implementing ReplicaSet awareness
+      Time.parse(pod_json["metadata"]["creationTimestamp"]) >= (@deploy_started - 30.seconds)
     end
   end
 end