Add copious debugging with --debug

- add new file "cask/utils.rb" analogous to "utils.rb" in Homebrew
- define odebug and odumpcask, analogs of ohai and friends, but
  which only give output when --debug is in effect
- move the debug setting from an instance variable in Cask::CLI
  to a method Cask.debug, defined in "lib/cask/options.rb", which
  was added in #2276. (Perhaps options.rb should be merged back
  into Cask::CLI).
- sprinkle odebug statements liberally throughout the codebase
- update tests

lib/cask.rb

@@ -29,6 +29,7 @@ require 'cask/source'
 require 'cask/system_command'
 require 'cask/underscore_supporting_uri'
 require 'cask/url'
+require 'cask/utils'
 
 require 'plist/parser'
 
@@ -39,6 +40,7 @@ class Cask
   include Cask::Options
 
   def self.init
+    odebug 'Creating directories'
     HOMEBREW_CACHE.mkpath unless HOMEBREW_CACHE.exist?
     unless caskroom.exist?
       ohai "We need to make Caskroom for the first time at #{caskroom}"
@@ -57,7 +59,10 @@ class Cask
   end
 
   def self.load(query)
-    Cask::Source.for_query(query).load
+    odebug 'Loading Cask definitions'
+    cask = Cask::Source.for_query(query).load
+    odumpcask cask
+    cask
   end
 
   def self.title

lib/cask/artifact.rb

@@ -43,6 +43,10 @@ module Cask::Artifact
   end
 
   def self.for_cask(cask)
-    artifacts.select { |artifact| artifact.me?(cask) }
+    odebug "Determining which artifacts are present in Cask #{cask}"
+    artifacts.select do |artifact|
+      odebug "Checking for artifact class #{artifact}"
+      artifact.me?(cask)
+    end
   end
 end

lib/cask/audit.rb

@@ -24,27 +24,32 @@ class Cask::Audit
 
 
   def _check_required_fields
+    odebug "Auditing required fields"
     add_error "url is required" unless cask.url
     add_error "version is required" unless cask.version
     add_error "homepage is required" unless cask.homepage
   end
 
   def _check_checksums
+    odebug "Auditing checksums"
     return if cask.sums == 0
     add_error "could not find checksum or no_checksum" unless cask.sums.is_a?(Array) && cask.sums.length > 0
   end
 
   def _check_no_checksums_if_latest
+    odebug "Verifying no_checkum with version 'latest'"
     add_error "you should use no_checksum when version is latest" if cask.version == "latest" && cask.sums.is_a?(Array)
   end
 
   def _check_download(download)
+    odebug "Auditing download"
     download.perform
   rescue => e
     add_error "download not possible: #{e.message}"
   end
 
   def _check_sourceforge_download_url_format
+    odebug "Auditing URL format"
     if _bad_sourceforge_url?
       add_warning "SourceForge URL format incorrect. See https://github.com/phinze/homebrew-cask/blob/master/CONTRIBUTING.md#sourceforge-urls"
     end

lib/cask/cli.rb

@@ -49,11 +49,11 @@ class Cask::CLI
     run_command(command, *rest)
   rescue CaskAlreadyInstalledError => e
     opoo e
-    $stderr.puts e.backtrace if @debug
+    $stderr.puts e.backtrace if Cask.debug
     exit 0
   rescue CaskError => e
     onoe e
-    $stderr.puts e.backtrace if @debug
+    $stderr.puts e.backtrace if Cask.debug
     exit 1
   end
 
@@ -112,7 +112,7 @@ class Cask::CLI
         Cask.no_binaries = true
       end
       opts.on("--debug") do |v|
-        @debug = true
+        Cask.debug = true
       end
     end
   end

lib/cask/cli/alfred.rb

@@ -47,6 +47,7 @@ class Cask::CLI::Alfred
     if linked?
       opoo "Alfred is already linked to homebrew-cask."
     else
+      odebug 'Linking Alfred scopes'
       save_alfred_scopes(alfred_scopes << Cask.caskroom)
       ohai "Successfully linked Alfred to homebrew-cask."
     end
@@ -58,6 +59,7 @@ class Cask::CLI::Alfred
     if !linked?
       opoo "Alfred is already unlinked from homebrew-cask."
     else
+      odebug 'Unlinking Alfred scopes'
       save_alfred_scopes(alfred_scopes.reject { |x| x == Cask.caskroom.to_s })
       ohai "Successfully unlinked Alfred from homebrew-cask."
     end
@@ -105,8 +107,10 @@ class Cask::CLI::Alfred
 
   def self.alfred_preference(key, value=nil)
     if value
+      odebug 'Writing Alfred preferences'
       @system_command.run('/usr/bin/defaults', :args => ['write', DOMAIN, key, %Q("#{value}")])
     else
+      odebug 'Reading Alfred preferences'
       @system_command.run('/usr/bin/defaults', :args => ['read', DOMAIN, key])
     end
   end

lib/cask/cli/audit.rb

@@ -17,6 +17,7 @@ class Cask::CLI::Audit
   end
 
   def audit(cask)
+    odebug "Auditing Cask #{cask}"
     @auditor.audit(cask, :audit_download => audit_download?)
   end
 

lib/cask/cli/checklinks.rb

@@ -2,6 +2,7 @@ class Cask::CLI::Checklinks
   def self.run(*args)
     casks_to_check = args.empty? ? Cask.all : args.map { |arg| Cask.load(arg) }
     casks_to_check.each do |cask|
+      odebug "Checking links for Cask #{cask}"
       checker = Cask::LinkChecker.new(cask)
       checker.run
       puts checker.summary

lib/cask/cli/create.rb

@@ -3,6 +3,7 @@ module Cask::CLI::Create
     raise CaskUnspecifiedError if arguments.empty?
     cask_name, *_ = *arguments
     cask_path = Cask.path(cask_name)
+    odebug "Creating Cask #{cask_name}"
 
     if cask_path.exist?
       raise CaskAlreadyCreatedError.new cask_name

lib/cask/cli/edit.rb

@@ -3,6 +3,7 @@ module Cask::CLI::Edit
     raise CaskUnspecifiedError if arguments.empty?
     cask_name, *_ = *arguments
     cask_path = Cask.path(cask_name)
+    odebug "Opening editor for Cask #{cask_name}"
     unless cask_path.exist?
       raise CaskUnavailableError, "#{cask_name}, use `brew cask create #{cask_name}` to make a new cask with this name"
     end

lib/cask/cli/home.rb

@@ -1,9 +1,11 @@
 module Cask::CLI::Home
   def self.run(*cask_names)
     if cask_names.empty?
+      odebug "Opening project homepage"
       system "/usr/bin/open", 'http://caskroom.io/'
     else
       cask_names.each do |cask_name|
+        odebug "Opening homepage for Cask #{cask_name}"
         cask = Cask.load(cask_name)
         system "/usr/bin/open", cask.homepage
       end

lib/cask/cli/info.rb

@@ -2,6 +2,7 @@ class Cask::CLI::Info
   def self.run(*cask_names)
     raise CaskUnspecifiedError if cask_names.empty?
     cask_names.each do |cask_name|
+      odebug "Getting info for Cask #{cask_name}"
       cask = Cask.load(cask_name)
       puts info(cask)
       Cask::Installer.print_caveats(cask)

lib/cask/cli/install.rb

@@ -4,6 +4,7 @@ class Cask::CLI::Install
     cask_names = args.reject { |a| a.chars.first == '-' }
     force = args.include? '--force'
     cask_names.each do |cask_name|
+      odebug "Installing Cask #{cask_name}"
       cask = Cask.load(cask_name)
       Cask::Installer.new(cask).install(force)
     end

lib/cask/cli/list.rb

@@ -9,6 +9,7 @@ class Cask::CLI::List
 
   def self.list_files(*cask_names)
     cask_names.each do |cask_name|
+      odebug "Listing files for Cask #{cask_name}"
       cask = Cask.load(cask_name)
       if cask.installed?
         Cask::PrettyListing.new(cask).print

lib/cask/cli/uninstall.rb

@@ -3,6 +3,7 @@ class Cask::CLI::Uninstall
     raise CaskUnspecifiedError if args.empty?
     cask_names = args.reject { |a| a.chars.first == '-' }
     cask_names.each do |cask_name|
+      odebug "Uninstalling Cask #{cask_name}"
       cask = Cask.load(cask_name)
       raise CaskNotInstalledError.new(cask) unless cask.installed?
       Cask::Installer.new(cask).uninstall

lib/cask/container.rb

@@ -18,7 +18,11 @@ class Cask::Container
   end
 
   def self.for_path(path, command)
+    odebug "Determining which containers to use"
     criteria = Cask::Container::Criteria.new(path, command)
-    containers.find { |c| c.me?(criteria) }
+    containers.find do |c|
+      odebug "Checking container class #{c}"
+      c.me?(criteria)
+    end
   end
 end

lib/cask/download.rb

@@ -21,7 +21,11 @@ class Cask::Download
     sums.each do |sum|
       unless sum.empty?
         computed = Checksum.new(sum.hash_type, Digest.const_get(sum.hash_type.to_s.upcase).file(path).hexdigest)
-        raise ChecksumMismatchError.new(sum, computed) unless sum == computed
+        if sum == computed
+          odebug "Checksums match"
+        else
+          raise ChecksumMismatchError.new(sum, computed)
+        end
         has_sum = true
       end
     end

lib/cask/download_strategy.rb

@@ -16,6 +16,7 @@ class Cask::DownloadStrategy < CurlDownloadStrategy
   end
 
   def _fetch
+    odebug "Calling curl with args #{curl_args}"
     curl(*curl_args)
   end
 

lib/cask/installer.rb

@@ -9,6 +9,7 @@ class Cask::Installer
   end
 
   def self.print_caveats(cask)
+    odebug "Printing caveats"
     unless cask.caveats.empty?
       ohai "Caveats"
       cask.caveats.each do |caveat|
@@ -22,6 +23,7 @@ class Cask::Installer
   end
 
   def install(force=false)
+    odebug "Cask::Installer.install"
     if @cask.installed? && !force
       raise CaskAlreadyInstalledError.new(@cask)
     end
@@ -43,22 +45,30 @@ class Cask::Installer
 
 
   def download
+    odebug "Downloading"
     download = Cask::Download.new(@cask)
     @downloaded_path = download.perform
+    odebug "Downloaded to -> #{@downloaded_path}"
+    @downloaded_path
   end
 
   def extract_primary_container
+    odebug "Extracting primary container"
     FileUtils.mkdir_p @cask.destination_path
     container = Cask::Container.for_path(@downloaded_path, @command)
     unless container
       raise "uh oh, could not identify primary container for #{@downloaded_path}"
     end
+    odebug "Using container class #{container} for #{@downloaded_path}"
     container.new(@cask, @downloaded_path, @command).extract
   end
 
   def install_artifacts
+    odebug "Installing artifacts"
     artifacts = Cask::Artifact.for_cask(@cask)
+    odebug "#{artifacts.length} artifact/s defined", artifacts
     artifacts.each do |artifact|
+      odebug "Installing artifact of class #{artifact}"
       artifact.new(@cask, @command).install
     end
   end
@@ -91,18 +101,23 @@ class Cask::Installer
   end
 
   def uninstall
+    odebug "Cask::Installer.uninstall"
     uninstall_artifacts
     purge_files
   end
 
   def uninstall_artifacts
+    odebug "Un-installing artifacts"
     artifacts = Cask::Artifact.for_cask(@cask)
+    odebug "#{artifacts.length} artifact/s defined", artifacts
     artifacts.each do |artifact|
+      odebug "Un-installing artifact of class #{artifact}"
       artifact.new(@cask, @command).uninstall
     end
   end
 
   def purge_files
+    odebug "Purging files"
     if @cask.destination_path.exist?
       @cask.destination_path.rmtree
     end

lib/cask/options.rb

@@ -11,5 +11,13 @@ module Cask::Options
     def no_binaries=(_no_binaries)
       @no_binaries = _no_binaries
     end
+
+    def debug
+      @debug ||= false
+    end
+
+    def debug=(_debug)
+      @debug = _debug
+    end
   end
 end

lib/cask/pkg.rb

@@ -13,9 +13,11 @@ class Cask::Pkg
   end
 
   def uninstall
+    odebug "Deleting pkg files"
     list('files').each_slice(500) do |file_slice|
       @command.run('/bin/rm', :args => file_slice.unshift('-f'), :sudo => true)
     end
+    odebug "Deleting pkg directories"
     _deepest_path_first(list('dirs')).each do |dir|
       if dir.exist?
         _with_full_permissions(dir) do
@@ -29,6 +31,7 @@ class Cask::Pkg
   end
 
   def forget
+    odebug "Unregistering pkg receipt (aka forgetting)"
     @command.run!('/usr/sbin/pkgutil', :args => ['--forget', package_id], :sudo => true)
   end
 

lib/cask/qualified_cask_name.rb

@@ -44,6 +44,7 @@ module Cask::QualifiedCaskName
       user, repo, cask = path_elements
     end
     repo.sub!(%r{^#{repo_prefix}}, '')
+    odebug "[user, repo, cask] might be [#{user}, #{repo}, #{cask}]"
     [user, repo, cask]
   end
 end

lib/cask/source.rb

@@ -20,8 +20,13 @@ module Cask::Source
   end
 
   def self.for_query(query)
-    source = sources.find { |s| s.me?(query) }
+    odebug "Translating '#{query}' into a valid Cask source"
+    source = sources.find do |s|
+      odebug "Testing source class #{s}"
+      s.me?(query)
+    end
     raise CaskUnavailableError.new(query) unless source
+    odebug "Using source class #{source}"
     source.new(query)
   end
 end

lib/cask/source/uri.rb

@@ -13,6 +13,7 @@ class Cask::Source::URI
     HOMEBREW_CACHE_CASKS.mkpath
     path = HOMEBREW_CACHE_CASKS.join(File.basename(uri))
     ohai "Downloading #{uri}"
+    odebug "Download target -> #{path.to_s}"
     curl(uri, '-o', path.to_s)
     Cask::Source::Path.new(path).load
   rescue ErrorDuringExecution

lib/cask/system_command.rb

@@ -1,6 +1,7 @@
 class Cask::SystemCommand
   def self.run(command, options={})
     command = _process_options(command, options)
+    odebug "Executing: #{command}"
     output = ''
     IO.popen(command, 'r+') do |pipe|
       if options[:input]

lib/cask/utils.rb

@@ -0,0 +1,32 @@
+
+# see Homebrew Library/Homebrew/utils.rb
+
+require 'yaml'
+
+# monkeypatch Tty
+class Tty
+  class << self
+    def magenta; color 35; end
+  end
+end
+
+def odebug title, *sput
+  if Cask.respond_to?(:debug) and Cask.debug
+    width = Tty.width * 4 - 6
+    if $stdout.tty? and title.to_s.length > width
+      title = title.to_s[0, width - 3] + '...'
+    end
+    puts "#{Tty.magenta}==>#{Tty.white} #{title}#{Tty.reset}"
+    puts sput unless sput.empty?
+  end
+end
+
+def odumpcask cask
+  if Cask.respond_to?(:debug) and Cask.debug
+    odebug "Cask instance dumps in YAML:"
+    odebug "Cask instance toplevel:", cask.to_yaml
+    [:homepage, :url, :version, :sums, :artifacts, :caveats].each do |method|
+      odebug "Cask instance method '#{method}':", cask.send(method).to_yaml
+    end
+  end
+end

test/cask/cli/options_test.rb

@@ -107,9 +107,10 @@ describe Cask::CLI do
   end
 
   describe "--debug" do
-    it "sets the CLI's debug variable to true" do
+    it "sets the Cask debug method to true" do
       Cask::CLI.process_options %w{help --debug}
-      Cask::CLI.instance_variable_get(:@debug).must_equal true
+      Cask.debug.must_equal true
+      Cask.debug = false
     end
   end