proposal: debug keyword

S

Simon Strandgaard

A debug keyword which enables debug-output for a specific method.
I have found its useful when there is many testcases which fails
at the same time, letting me faster identify where the problem is.

I think this would be a good idea to have distributed with Ruby?
I am thinking of submitting an RCR, should I do this?



Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

If we type 'debug :test_a1', then we get the following output

server> ruby example.rb
Loaded suite TestA
Started
test_a1(TestA): before #test_a1
A#compute, begin
A#dostuff, begin
A#dostuff, end
A#compute, end
after #test_a1
..

Finished in 0.002609 seconds.

1 tests, 1 assertions, 0 failures, 0 errors
server>

However if we doesn't type it, then we get our normal output.

server> ruby example.rb
Loaded suite TestA
Started
test_a1(TestA): .

Finished in 0.001572 seconds.

1 tests, 1 assertions, 0 failures, 0 errors
server>



Its a bit hackish, but it works.

server> expand -t2 debug_keyword.rb
BEGIN {
$debug = false
}

# purpose:
# make it easy to enable/disable debugging
#
# if $debug == nil then output are disabled
# if $debug != nil then output are enabled
module Debuggable
def printx(*args)
if $debug
super(*args)
end
end
def puts(*args)
if $debug
super(*args)
end
end
def p(*args)
if $debug
super(*args)
end
end
def print(*args)
if $debug
super(*args)
end
end
end


# purpose:
# enable $debug flag inside a method
#
# class Test
# include Debuggable
# def test_x; p 42; end
# debug :test_x
# end
# Test.new.test_x #-> (before 'test_x') 42 (after 'test_x')
#
class Module
# enable the global debug flag for just a single method
def debug(*args)
debug_methods = private_instance_methods(true)
args.each do |symbol|
name = symbol.id2name
org = "_debug_"+name
if debug_methods.include?(org)
$stderr.puts "ERROR: already debugging method: #{name}"
next
end
begin
meth = instance_method(symbol)
rescue => e
$stderr.puts "ERROR: symbol2method failure, " + e.inspect
next
end
arguments = (meth.arity != 0) ? "(*a,&b)" : "(&b)"
alias_method org, name
module_eval %{
def #{name}#{arguments}
$stdout.puts("before ##{name}")
debug, $debug = $debug, true
result = #{org}#{arguments}
$stdout.puts("after ##{name}")
result
ensure
$debug = debug
end
private :#{org}
}
end
end
end
server>


server> expand -t2 example.rb
require 'debug_keyword'
class A
include Debuggable
def dostuff
puts "A#dostuff, begin"
puts "A#dostuff, end"
end
def compute
puts "A#compute, begin"
dostuff
puts "A#compute, end"
42
end
end

require 'test/unit'
class TestA < Test::Unit::TestCase
def test_a1
assert_equal(42, A.new.compute)
end
debug :test_a1 # enable/disable debugging
end

require 'test/unit/ui/console/testrunner'
Test::Unit::UI::Console::TestRunner.run(TestA, Test::Unit::UI::VERBOSE)
server>
 
R

Robert Klemme

Simon Strandgaard said:
A debug keyword which enables debug-output for a specific method.
I have found its useful when there is many testcases which fails
at the same time, letting me faster identify where the problem is.

I think this would be a good idea to have distributed with Ruby?
I am thinking of submitting an RCR, should I do this?



Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

More precisely it switches all output on or off in a method. And that's
what I don't like about it: in your example class A behavior of "puts",
"print" etc. changes depending on the $debug flag. That's IMHO not
compliant with POLS. I'd prefer to have specialized methods for debug
printing.

Kind regards

robert
 
S

Simon Strandgaard

Simon Strandgaard said:
Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

More precisely it switches all output on or off in a method. And that's
what I don't like about it: in your example class A behavior of "puts",
"print" etc. changes depending on the $debug flag. That's IMHO not
compliant with POLS.

Agree it isn't POLS, but debugging is sometimes tuff.

I never remove print statements.. because I one day might need that
information. Then a debug keyword + Debuggable module is practical.
I have attached a debug output from a testcase (my regexp project).

I have used logfiles in the past.. but in conjunction with
unittesting they seems to be not needed.

I'd prefer to have specialized methods for debug printing.

Please enlighten me. How do you debug ?


It would be nice to identify a good model for advanced debugging with
Test::Unit.

--
Simon Strandgaard


Loaded suite TestScanner
Started
test_verbose_alt_rep1(TestScanner): before #test_verbose_alt_rep1
regexp="(foob|fo|o)*bar"
+-Sequence
+-Repeat greedy{0,-1}
| +-Group register=1
| +-Alternation
| +-Sequence
| | +-Literal "f"
| | +-Literal "o"
| | +-Literal "o"
| | +-Literal "b"
| +-Sequence
| | +-Literal "f"
| | +-Literal "o"
| +-Literal "o"
+-Literal "b"
+-Literal "a"
+-Literal "r"
input="xfoobarx"
----------------------------------------
execute at position 0
repeat 0
visitor#set_state from active into inactive
match "b" at position 0
path end = expected "b" but got "x"
check_integrity history.size=1
index-stack=[0]
integrity "bar" (line 0)

next_path zero. found=false lazy=false state=active index=0 has_match=false
clear history
replace zero with one
visitor#set_state from inactive into active
visitor#set_memento
group_open register=1
alternation 0
match "f" at position 0
path end = expected "f" but got "x"
check_integrity history.size=2
index-stack=[1, 0]
integrity "foob bar" (line 1)

next_path alternation. index=0->1
visitor#set_memento
match "f" at position 0
path end = expected "f" but got "x"
check_integrity history.size=2
index-stack=[1, 1]
integrity "fo bar" (line 2)

next_path alternation. index=1->2
visitor#set_memento
match "o" at position 0
path end = expected "o" but got "x"
check_integrity history.size=2
index-stack=[1, 2]
integrity "o bar" (line 3)

next_path alternation. index=2->3, exhausted
skip, path end = exhausted
next_path one. found=false lazy=false state=active index=0 has_match=false
clear history
skip, path end = is done
execute at position 1
repeat 0
visitor#set_state from active into inactive
match "b" at position 1
path end = expected "b" but got "f"
check_integrity history.size=1
index-stack=[0]
integrity "bar" (line 4)

next_path zero. found=false lazy=false state=active index=0 has_match=false
clear history
replace zero with one
visitor#set_state from inactive into active
visitor#set_memento
group_open register=1
alternation 0
match "f" at position 1
match "o" at position 2
match "o" at position 3
match "b" at position 4
group_close register=1
visitor#set_state from active into inactive
one-end
match "b" at position 5
path end = expected "b" but got "a"
check_integrity history.size=3
index-stack=[1, 0]
integrity "foob bar" (line 5)

next_path zero. found=false lazy=false state=active index=1 has_match=false
clear history
replace zero with one
visitor#set_state from inactive into active
visitor#set_memento
group_open register=1
alternation 0
match "f" at position 5
path end = expected "f" but got "a"
check_integrity history.size=4
index-stack=[2, 0, 0]
integrity "foob foob bar" (line 6)

next_path alternation. index=0->1
visitor#set_memento
match "f" at position 5
path end = expected "f" but got "a"
check_integrity history.size=4
index-stack=[2, 0, 1]
integrity "foob fo bar" (line 7)

next_path alternation. index=1->2
visitor#set_memento
match "o" at position 5
path end = expected "o" but got "a"
check_integrity history.size=4
index-stack=[2, 0, 2]
integrity "foob o bar" (line 8)

next_path alternation. index=2->3, exhausted
skip, path end = exhausted
next_path one. found=false lazy=false state=active index=1 has_match=false
clear history
skip, path end = is done
next_path alternation. index=0->1
visitor#set_memento
match "f" at position 1
match "o" at position 2
group_close register=1
visitor#set_state from active into inactive
one-end
match "b" at position 3
path end = expected "b" but got "o"
check_integrity history.size=3
index-stack=[1, 1]
integrity "fo bar" (line 9)

next_path zero. found=false lazy=false state=active index=1 has_match=false
clear history
replace zero with one
visitor#set_state from inactive into active
visitor#set_memento
group_open register=1
alternation 0
match "f" at position 3
path end = expected "f" but got "o"
check_integrity history.size=4
index-stack=[2, 1, 0]
integrity "fo foob bar" (line 10)

next_path alternation. index=0->1
visitor#set_memento
match "f" at position 3
path end = expected "f" but got "o"
check_integrity history.size=4
index-stack=[2, 1, 1]
integrity "fo fo bar" (line 11)

next_path alternation. index=1->2
visitor#set_memento
match "o" at position 3
group_close register=1
visitor#set_state from active into inactive
one-end
match "b" at position 4
match "a" at position 5
match "r" at position 6
last
path end = reached last node
check_integrity history.size=5
index-stack=[2, 1, 2]
integrity "fo o bar" (line 12)

next_path zero. found=true lazy=false state=active index=2 has_match=false
remember zero and clear
replace zero with one
visitor#set_state from inactive into active
visitor#set_memento
group_open register=1
alternation 0
match "f" at position 4
path end = expected "f" but got "b"
check_integrity history.size=6
index-stack=[3, 1, 2, 0]
integrity "fo o foob bar" (line 13)

next_path alternation. index=0->1
visitor#set_memento
match "f" at position 4
path end = expected "f" but got "b"
check_integrity history.size=6
index-stack=[3, 1, 2, 1]
integrity "fo o fo bar" (line 14)

next_path alternation. index=1->2
visitor#set_memento
match "o" at position 4
path end = expected "o" but got "b"
check_integrity history.size=6
index-stack=[3, 1, 2, 2]
integrity "fo o o bar" (line 15)

next_path alternation. index=2->3, exhausted
skip, path end = exhausted
next_path one. found=false lazy=false state=active index=2 has_match=true
clear history
install match
visitor#set_memento
skip, path end = is done
next_path alternation. index=2->3, found
skip, path end = found
next_path one. found=true lazy=false state=active index=1 has_match=true
remember one and clear
install match
visitor#set_memento
skip, path end = is done
next_path alternation. index=1->2, found
skip, path end = found
next_path one. found=true lazy=false state=active index=0 has_match=true
remember one and clear
install match
visitor#set_memento
----- BEGIN before activate -----
content of history stack
0: ONE_0 quantifier_id=0
1: ALT_1
2: ONE_1 quantifier_id=0
3: ALT_2
4: ZERO_2 quantifier_id=0
quantifier information
0: active found=no
----- END before activate -----
activate_next
found zero/one
activate_inactive
----- BEGIN after activate -----
content of history stack
0: ONE_0 quantifier_id=0
1: ALT_1
2: ONE_1 quantifier_id=0
3: ALT_2
4: ZERO_2 quantifier_id=0
quantifier information
0: done found=no
----- END after activate -----
skip, path end = is done
next_path zero. found=true lazy=false state=done index=2 has_match=false
skip, path end = done
next_path alternation. index=2->3, found
skip, path end = found
next_path one. found=true lazy=false state=done index=1 has_match=false
skip, path end = done
next_path alternation. index=1->2, found
skip, path end = found
next_path one. found=true lazy=false state=done index=0 has_match=false
skip, path end = done
----------------------------------------
result=["foobar", "o"]
after #test_verbose_alt_rep1
..

Finished in 0.026799 seconds.

1 tests, 1 assertions, 0 failures, 0 errors
 
R

Robert Klemme

Simon Strandgaard said:
Simon Strandgaard said:
Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

More precisely it switches all output on or off in a method. And that's
what I don't like about it: in your example class A behavior of "puts",
"print" etc. changes depending on the $debug flag. That's IMHO not
compliant with POLS.

Agree it isn't POLS, but debugging is sometimes tuff.

Taff? Well, yes it is.
I never remove print statements.. because I one day might need that
information. Then a debug keyword + Debuggable module is practical.
I have attached a debug output from a testcase (my regexp project).

I have used logfiles in the past.. but in conjunction with
unittesting they seems to be not needed.



Please enlighten me. How do you debug ?

? Sorry if I wasn't clear enough. The thing I don't like is the naming
of the methods used for debug printing. I mean, rather use different
names than "puts", "print" etc. in order to be able to have regular output
as well as debug output. Also it helps in identifying lines that can be
taken out once the code is ok. (Ok, you don't take them out so this
argument doesn't count for you - but other IMHO.)

Is there a reason why your debug output methods need to override methods
defined in Kernel?
It would be nice to identify a good model for advanced debugging with
Test::Unit.

Yeah.

robert
 
S

Simon Strandgaard

Simon Strandgaard said:
Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

More precisely it switches all output on or off in a method. And that's
what I don't like about it: in your example class A behavior of "puts",
"print" etc. changes depending on the $debug flag. That's IMHO not
compliant with POLS.

Agree it isn't POLS, but debugging is sometimes tuff.

Taff? Well, yes it is.

First I tried with 'toff' but it looked wrong ;-)

? Sorry if I wasn't clear enough. The thing I don't like is the naming
of the methods used for debug printing. I mean, rather use different
names than "puts", "print" etc. in order to be able to have regular output
as well as debug output. Also it helps in identifying lines that can be
taken out once the code is ok. (Ok, you don't take them out so this
argument doesn't count for you - but other IMHO.)

Understandable.. using puts, print has drawbacks. Good suggestion, I
think I will replace them with something else.

Any ideas for a good name?

debug replacement puts -> #debug_puts, #dputs
debug replacement p -> #debug_p, #dp

maybe just turn the 'p' in 'puts' upsidedown, so it becomes a 'd' => duts?

Is there a reason why your debug output methods need to override methods
defined in Kernel?

do you mean 'class Module'?

Yes there is a good reason.. by having it here, allows me to use
the debug keyword inside modules. Like this:

module TodoVerbose
include MatchVerbose
debug :test_verbose_alt_rep1
#undef test_verbose_alt_rep1
#debug :test_verbose_alt_rep2
undef test_verbose_alt_rep2
#debug :test_verbose_repeat1
undef test_verbose_repeat1
#debug :test_verbose_repeat2
undef test_verbose_repeat2
debug :test_verbose_repeat3
undef test_verbose_repeat3
end

If the 'debug' keyword was defined in class Object, then
above wouldn't be possible.


Agree ;-)
 
R

Robert Klemme

Simon Strandgaard said:
Simon Strandgaard said:
On Wed, 25 Feb 2004 14:26:36 +0100, Robert Klemme wrote:
Its syntax is

debug :method [, :method]*

What it does is to enable the global flag $debug.

More precisely it switches all output on or off in a method. And that's
what I don't like about it: in your example class A behavior of "puts",
"print" etc. changes depending on the $debug flag. That's IMHO not
compliant with POLS.

Agree it isn't POLS, but debugging is sometimes tuff.

Taff? Well, yes it is.

First I tried with 'toff' but it looked wrong ;-)

Actually, "tough" looks even better. :))
Understandable.. using puts, print has drawbacks. Good suggestion, I
think I will replace them with something else.

Any ideas for a good name?

debug replacement puts -> #debug_puts, #dputs
debug replacement p -> #debug_p, #dp

Hm... I'd go for "d_puts" which is immediately distinguished from "puts"
but is not so much typing overhead as the more verbose "debug_puts".
maybe just turn the 'p' in 'puts' upsidedown, so it becomes a 'd' => duts?

http://www.best-lyrics-zone.net/Upside_Down_Lyrics.html
:)


do you mean 'class Module'?

Nope, that question was referring to the naming of the methods which in
turn lead to shadowing the original methods "puts" etc. (see above). But
I think we have sorted that out by now. :)
Yes there is a good reason.. by having it here, allows me to use
the debug keyword inside modules. Like this:

Of course.

Agree ;-)

You agree to yourself? That's a good sign - at least you don't seem to
suffer from MPD* (at leat not at the moment. :))

Cheers

robert


* http://www.multiple-personality.com/
 
S

Steve Tuckner

Simon said:
Please enlighten me. How do you debug ?


It would be nice to identify a good model for advanced debugging with
Test::Unit.
I too am interested in how others debug their unit tests (or code in
general). I am preparing to release my vrtools library an am removing my
trace statements in them because it seems like an unnecessary dependency
(perhaps just my way of working). Below is my trace module that I use
all the time. I once tried log4r but didn't like it because it didn't
seem easy to turn on and off debugging when I needed it to. My output
includes the code and line number which my editor links up when the unit
test is done running. Also it includes a time stamp to help with any
timing related issues. I can include and exclude debug in various ways
and direct output to a file. It all works pretty well for me (not
perfectly -- for example some things could be named better).

So my requirements for a simple tracing/debugging system are for me:

1. Trace output should include file/line number plus time stamp
2. Need to be able to turn it on and off at run time
3. Need to be able to filter which debug statements come out by debug
level, function, file, possibly other considerations
4. Need to be able to redirect output to a file

What are others requirements?

Maybe log4r provides all these capabilities and if so enlighten me please.

Steve Tuckner

----------------- Examples of use ---------------------------
require "my/mytrace" # to use my tracing this
creates a global $TRACE of class Tracer

$TRACE.set_level 5 # sets the level under which
traces will appear
$TRACE.exclude_files("foo.rb") # this excludes any traces in
foo.rb from coming out
$TRACE.include_files("bar.rb") # this overrides exculsions to
only allow traces from included files
$TRACE.exclude_functions:)foo, :bar) # this excludes any traces from
coming out from these functions (no matter the class)
$TRACE.set_output("out.txt") # write each statement to the
output file and close it after every trace (this is not as bad as it
sounds and if the program dies you definitiely get all the trace)

$TRACE.debug 5, "this is a trace" # this is the basic trace
statement with level 5

----------------- Example of program and output ---------------------------
--------------------------- tracetest.rb ----------
require "my/mytrace"

def foo
$TRACE.debug 5, "I am in foo"
puts "not a debug statement"
end

$TRACE.set_level 5
foo
$TRACE.set_level 0
foo

-------------------------- output -----------------
[tracetest.rb:4 ] [02/25/04 08:47:51] I am in foo
not a debug statement
not a debug statement
--------------------------------------------------

----------------- Trace code
------------------------------------------------

class Tracer
def initialize
@trace_level = 0
@file = nil
@width = 25
@excluded_functions = []
@excluded_files = []
@output_to_screen_always = false
end

def set_width(width)
@width = width
end

def trace(str, level=1)
#old_dollar_equal = $=
#$= = false

if @trace_level >= level then
m = /([\w_]+\.rb):(\d+):in `(.*)'/.match(caller[1])
if m then
filename = m[1]
line = m[2].to_i
function = m[3]

t = Time.current.strftime("%m/%d/%y %H:%M:%S")
str = sprintf "[%-#{@width}s] [%s] %s",
"#{m[1]}:#{m[2]}", t, str

if @included_files then
return unless @included_files.include?(filename)
else
if @excluded_functions.include?(function) then
return
end

if @excluded_files.include?(filename) then
return
end
end
end

if @filename then
File.open(@filename, "a") {|f| f.print str, "\n"}
end

if !@filename || @output_to_screen_always then
puts str
$stdout.flush
end
end
ensure
#$= = old_dollar_equal
end

def debug(level, str)
trace(str, level)
end

def set_level(level)
@trace_level = level
end

def set_level_include(level, included_files)
@trace_level = level
@included_files = included_files
end

def set_output(filename)
@filename = filename
File.open(@filename, "w") {}
end

def set_output_io(io)
@io = io
end

def set_output_to_screen_always
@output_to_screen_always = true
end
def exclude_functions(functions)
@excluded_functions += functions
end

def exclude_files(filenames)
@excluded_files += filenames
end
end

# define the $TRACE variable if not already defined
if !$TRACE then
$TRACE = Tracer.new
end
 
C

Charles Comstock

Simon said:
BTW: I had to change my taste of music so it reflect the language I am using

diamonds are forever
lucy in the sky with diamonds
diamonds are a girls best friend

It would be nice if we had macros for the debug stuff, so the code would
never even be seen when you didn't do debug code. For instance if
instead for debug output you had a debug block, which was evaled and
added to the code on the first pass, so it would execute all further
passes. This would only occur if $debug was set, otherwise the code
would never be evaled, and we wouldn't even test to see if the verbose
flag was set, and thus it would never actually get executed. I suppose
this could also be simulated if we had constant propagation in the
interpreter, so that a constant if expression would be eliminated.

Another comment though, I really hate having only the ability to turn
debug output off globally. It's much nicer to be able to turn it all on
or off, but also be able to turn it on per the scope you are in.

Charlie
 
R

Robert Klemme

Charles Comstock said:
It would be nice if we had macros for the debug stuff, so the code would
never even be seen when you didn't do debug code. For instance if
instead for debug output you had a debug block, which was evaled and
added to the code on the first pass, so it would execute all further
passes. This would only occur if $debug was set, otherwise the code
would never be evaled, and we wouldn't even test to see if the verbose
flag was set, and thus it would never actually get executed. I suppose
this could also be simulated if we had constant propagation in the
interpreter, so that a constant if expression would be eliminated.

I don't mandate a preprocessor since Ruby is flexible enough and we all
know what Bjarne said about one of his biggest mistakes with C++... :)

IMHO this is as efficient as it can get without a macro preprocessor. The
overhead is a single method call and a boolean test for non debug mode:

module Kernel
def debug
yield if $DEBUG
end
end

Then you can do:

def foo
debug {
# complex calculations might be here
}

# normal operation
end

Another comment though, I really hate having only the ability to turn
debug output off globally. It's much nicer to be able to turn it all on
or off, but also be able to turn it on per the scope you are in.

That's what Simon's suggestion was all about. :)

robert
 
S

Simon Strandgaard

On Wed, 25 Feb 2004 13:16:50 +0100, Simon Strandgaard wrote:
[snip]
I think this would be a good idea to have distributed with Ruby?
I am thinking of submitting an RCR, should I do this?

Question still stands, should I make an RCR out of it?


Consideration if the name 'debug' is ok?

Temporary enabling a global flag is more general,
perhaps its better to make a temporary-set method

temp_set $global_variable, :method

Instead of naming it 'debug', then maybe name it

temp_set_debug :method


What should be in the RCR?
the 'temp_set' thing or the 'debug' keyword thing?


Sorry for rambling.. needs more input ;-)
 
R

Robert Klemme

Simon Strandgaard said:
On Wed, 25 Feb 2004 13:16:50 +0100, Simon Strandgaard wrote:
[snip]
I think this would be a good idea to have distributed with Ruby?
I am thinking of submitting an RCR, should I do this?

Question still stands, should I make an RCR out of it?


Consideration if the name 'debug' is ok?

When switching debugging for certain methods "debug_method" is more
appropriate IMHO. "debug" implies some global thingy. My 0.02 EUR...
Temporary enabling a global flag is more general,
perhaps its better to make a temporary-set method

temp_set $global_variable, :method

Instead of naming it 'debug', then maybe name it

temp_set_debug :method


What should be in the RCR?
the 'temp_set' thing or the 'debug' keyword thing?


Sorry for rambling.. needs more input ;-)

Hm... Just as food for thought: how about some more aspect oriented
solution, i.e., debug aspects to switch on and off (see attachment).

Regards

robert
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

Forum statistics

Threads
473,989
Messages
2,570,207
Members
46,783
Latest member
RickeyDort

Latest Threads

Top