Bug #9491

Remove --debug option and use a formatter instead

Added by anonym 2015-05-28 16:28:02 . Updated 2015-09-22 15:08:44 .

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Test suite
Target version:
Tails_1.6
Start date:
2015-05-28
Due date:
% Done:

100%

Feature Branch:
test/9491-debug-cucumber-formatter
Type of work:
Code
Blueprint:

Starter:
Affected tool:
Deliverable for:

Description

Now that Feature #9424 is solved, we could do something pretty interesting. We could remove the --debug option and replace it with a formatter that includes debug information. It’d be nice to call it simply debug, but it already exists (and is useful when developing new formatters, apparently), but we could override it with our one, or pick a new name, like pretty_debug. So, this formatter would be the pretty one, but also have all the debug info we print to STDERR, and the info we let some subprocesses (sikuli, guestfs) print to STDERR when --debug is enabled.

To make a formatter that we can print to with e.g. a debug_log() function is pretty straight-forward:

def debug_log(message)
  return if not($config["DEBUG"])
  $debug_log_fns.each { |fn| fn.call(message) }
end

require 'cucumber/formatter/pretty'
module ExtraFormatters
  class PrettyDebug < Cucumber::Formatter::Pretty
    def initialize(*args)
      super(*args)
      $debug_log_fns ||= []
      $debug_log_fns << self.method(:debug_log)
    end

    def debug_log(msg)
      @io.puts(msg)
    end
  end
end

module Cucumber
  module Cli
    class Options
      BUILTIN_FORMATS['debug'] = ['ExtraFormatters::PrettyDebug', 'Prints the feature with debuggin information - in colours.']
    end
  end
end


The hard part is to connect the STDOUT/STDERR of subprocesses so it writes to the formatters destination (which can be a file or the terminal/stdout). I only have some vague ideas based on crazy stuff that the JUnit formatter does with some sort of stream interceptor. Not sure at all if that will work out though.

Now, why would we want to do this? Well, the output when --debug is enabled is quite hard to follow given the amount of debugging info we print (especially for Tor leak tests) so I generally run without it. However, when there’s an issue I often regret not having the debug info, since some issues do not reappear every time due to our robustness issues. But if we had this we could run cucumber with --format pretty --format debug --out /tmp/debug.log so that we get the pretty non-debug written to the terminal that is easy to follow, and the full debug info (including the pretty output, for the all-important context) written to a file that we can investigate if there’s some unexpected error. Awesome! Currently we can do the opposite (pretty + debug to the terminal, pretty only to file) with --debug -- --format pretty --format pretty --out /tmp/pretty.log which isn’t as nice, but I actually do this quite often.

Note if we have this we can also kill run_test_suite’s --log-to-file option.

Subtasks

History

#1 Updated by intrigeri 2015-05-29 09:01:27

> Now, why would we want to do this? Well, the output when --debug is enabled is quite hard to follow given the amount of debugging info we print (especially for Tor leak tests) so I generally run without it. However, when there’s an issue I often regret not having the debug info, since some issues do not reappear every time due to our robustness issues. But if we had this we could run cucumber with --format pretty --format debug --out /tmp/debug.log so that we get the pretty non-debug written to the terminal that is easy to follow, and the full debug info (including the pretty output, for the all-important context) written to a file that we can investigate if there’s some unexpected error. Awesome!

Same experience here. Indeed this would be great!

#2 Updated by intrigeri 2015-08-28 10:29:21

  • Subject changed from Remove --debug option and user a formatter instead to Remove --debug option and use a formatter instead

#3 Updated by anonym 2015-09-10 14:13:48

  • Status changed from Confirmed to In Progress

Applied in changeset commit:1e01b8d9f1f10bc62575e1d0f149602f9ffbefda.

#4 Updated by anonym 2015-09-10 14:30:57

  • Assignee changed from anonym to kytv
  • Target version set to Tails_1.6
  • % Done changed from 0 to 50
  • QA Check set to Ready for QA
  • Feature Branch set to test/9491-debug-cucumber-formatter

Done. Also simplified our existing extra hooks code which fixed a corner case bug when the first formatter is used twice (which is completely reasonable, i.e. you want to clone the terminal to a file, i.e. what --log-to-file does). Also went mad and invented an “inotify-driven pseudo fifo logging system”. Yeah, CRuby’s threading/concurrency/parallelism support is so bad when IO is involved that we have to resort to something like this for the “subprocess logging” problem mentioned in the ticket description.

So, if/when this is merged I will personally always run the test suite like this:

./run_test_suite [run_test_suite options] -- --format pretty --format debug --out /tmp/debug.log [.feature files]


so I get the normal pretty output without debugging info to the terminal, and the pretty output with debugging printed to a file. No need to re-run when there’s an error you didn’t understand and wished you had run it with --debug in the first place (and maybe it won’t even trigger this time). Sweet!

#5 Updated by anonym 2015-09-11 15:48:04

I had forgotten to hook otr-bot/chatbot helper into the new logging system. Pushed a few more commits for that.

(Thanks for the work on Bug #9375, kytv, which reminded me of this! :))

#6 Updated by bertagaz 2015-09-13 04:45:02

  • Assignee changed from kytv to bertagaz

Stealing review from Kytv, as I’ve been asked to do so on the mailing-list

#7 Updated by bertagaz 2015-09-13 05:30:35

  • Status changed from In Progress to Fix committed
  • % Done changed from 50 to 100

Applied in changeset commit:1ae520bdaee2a974259f782c848dd920ba1bc8db.

#8 Updated by bertagaz 2015-09-13 05:31:40

  • Assignee deleted (bertagaz)
  • QA Check changed from Ready for QA to Pass

Merged, awesome work!

#9 Updated by intrigeri 2015-09-14 09:20:15

  • Status changed from Fix committed to In Progress
  • Assignee set to anonym
  • QA Check changed from Pass to Dev Needed

I see that:

  • run_test_suite still sets DEBUG=
  • wiki/src/contribute/release_process/test/usage.mdwn still documents the DEBUG option, which is apparently not supported anymore; should it be kept and turn on the debug formatter, or just disappear for real?

#10 Updated by anonym 2015-09-15 07:10:03

  • Assignee changed from anonym to intrigeri
  • QA Check changed from Dev Needed to Ready for QA

intrigeri wrote:
> I see that:
>
> * run_test_suite still sets DEBUG=

Indeed. I probably sanity checked with git grep DEBUG -- features/ which indeed wouldn’t catch that instance…

> * wiki/src/contribute/release_process/test/usage.mdwn still documents the DEBUG option, which is apparently not supported anymore;

… or these! Oops. Fixed!

Also, I pushed a very critical fixup to commit commit:1d4156e. Please merge! That broke a lot of steps, and I’m not even sure how both me and bert missed it. :/ Kudos to kytv for finding it and verifying that my fix works!

> should it be kept and turn on the debug formatter, or just disappear for real?

I think it should disappear. The --format way is very flexible, and I’m not sure how we could keep that while also making our wrapper support messing with them. Ok?

#11 Updated by intrigeri 2015-09-15 07:51:45

  • Status changed from In Progress to Fix committed

Applied in changeset commit:9d016567a048f1daf93f95b080ffb18e54aa15b5.

#12 Updated by intrigeri 2015-09-15 07:52:51

  • Assignee deleted (intrigeri)
  • QA Check changed from Ready for QA to Pass

anonym wrote:
> intrigeri wrote:
>> should it be kept and turn on the debug formatter, or just disappear for real?
>
> I think it should disappear. The --format way is very flexible, and I’m not sure how we could keep that while also making our wrapper support messing with them. Ok?

OK.

#13 Updated by intrigeri 2015-09-15 08:04:29

  • Status changed from Fix committed to In Progress
  • Assignee set to anonym
  • % Done changed from 100 to 70
  • QA Check changed from Pass to Dev Needed

When /tmp/TailsToaster doesn’t exist yet I see:

Virtual X framebuffer started on display :1
Capturing guest display into --view
[info] Sikuli vision engine loaded.
/tmp/TailsToaster/debug_log_pseudo_fifo (No such file or directory) (FileNotFoundException)
/srv/tails/git/features/support/helpers/sikuli_helper.rb:46:in `new'
/srv/tails/git/features/support/helpers/sikuli_helper.rb:46:in `<top (required)>'
/usr/lib/ruby/vendor_ruby/cucumber/rb_support/rb_language.rb:94:in `load'
/usr/lib/ruby/vendor_ruby/cucumber/rb_support/rb_language.rb:94:in `load_code_file'
/usr/lib/ruby/vendor_ruby/cucumber/runtime/support_code.rb:237:in `load_file'
/usr/lib/ruby/vendor_ruby/cucumber/runtime/support_code.rb:97:in `block in load_files!'
/usr/lib/ruby/vendor_ruby/cucumber/runtime/support_code.rb:96:in `each'
/usr/lib/ruby/vendor_ruby/cucumber/runtime/support_code.rb:96:in `load_files!'
/usr/lib/ruby/vendor_ruby/cucumber/runtime.rb:242:in `load_step_definitions'
/usr/lib/ruby/vendor_ruby/cucumber/runtime.rb:65:in `run!'
/usr/lib/ruby/vendor_ruby/cucumber/cli/main.rb:33:in `execute!'
/usr/bin/cucumber:6:in `<main>'

#14 Updated by anonym 2015-09-15 08:35:08

  • Assignee changed from anonym to intrigeri
  • QA Check changed from Dev Needed to Ready for QA

intrigeri wrote:
> When /tmp/TailsToaster doesn’t exist yet I see:

Fix pushed!

#15 Updated by intrigeri 2015-09-15 09:57:36

  • Status changed from In Progress to Fix committed
  • % Done changed from 70 to 100

Applied in changeset commit:4ddbc9da61fd6a6109a311da753fe9f4c1f93aeb.

#16 Updated by intrigeri 2015-09-15 09:58:29

  • Assignee deleted (intrigeri)
  • QA Check changed from Ready for QA to Pass

#17 Updated by intrigeri 2015-09-15 10:00:28

anonym wrote:
> So, if/when this is merged I will personally always run the test suite like this:
> […]
> so I get the normal pretty output without debugging info to the terminal, and the pretty output with debugging printed to a file. No need to re-run when there’s an error you didn’t understand and wished you had run it with --debug in the first place (and maybe it won’t even trigger this time). Sweet!

Perhaps this could be made the default? IIRC one can drop such options in a cucumber.yml file somewhere.

#18 Updated by bertagaz 2015-09-22 15:08:44

  • Status changed from Fix committed to Resolved
  • QA Check deleted (Pass)