class Logger < Aspect
  def initialize(io = STDOUT)
    @io = io
  end
		 
  def _tick; "#{Time.now.strftime('%Y-%m-%d %X')}"; end

  def enter(method, object, exitstatus, *args)
    @io.puts "enter: #{_tick} #{object.class}##{method}: called with #{args.inspect}"
  end
    
  def exit(method, object, exitstatus, *args)
    @io.print "exit: #{_tick} #{object.class}##{method}: exited "
    if exitstatus.kind_of?(Array)
      @io.puts "normally returning #{exitstatus[0].inspect}"
    elsif exitstatus == true
      @io.puts "with exception '#{$!}'"
    else
      @io.puts 'normally'
    end
  end

  def senter(method, object, exitstatus, *args)
    @io.puts "senter: #{_tick} Entering #{object.object_id}##{method}"
  end

  def sexit(method, object, exitstatus, *args)
    @io.puts "sexit: #{_tick} Exiting #{object.object_id}##{method}"
  end
end

class Counter < Aspect
  attr_reader :incrementer_cnt
  
  def initialize
    @counters = {}
  end

  def wrap(target, *methods)
    super(target, :inc, nil, *methods)
  end

  def unwrap(target, *methods)
    super(target, :inc, nil, *methods)
  end

  def [](object, method)
    method = method.id2name if method.kind_of?(Symbol)
    @counters[object][method]
  end

  private
  def inc(method, object, *args)
    begin
      @counters[object][method] += 1
    rescue NameError
      @counters[object] = {} unless @counters[object]
      @counters[object][method] = 1
    end
  end  
end




class TestHello
  attr_reader :tt

  def say(hello)
    return hello + " world"
  end
  
  def inspect; object_id.inspect; end
  
  def sayz(*args)
    raise NotImplementedError, 'NYI!'
  end
end

class HistoryStdOut
  attr_reader :history
  def initialize
    @history = Array.new
  end
  def puts(str)
    if @last_was_print
      @history[-1] += str
    else
      @history.push str
    end
    @last_was_print = false
  end
  def print(str)
    @history.push str
    @last_was_print = true
  end
  def last; @history.last; end
end

class CodeWrapper < Aspect
  alias old_wrap wrap
  def wrap(target, *methods)
    wrap_with_code(target, "p 'pre'", "p 'post'", *methods)
  end
  def code_wrap(target, *methods)
    wrap_with_code(target,"CodeWrapper.enter","CodeWrapper.leave", *methods)
  end
  @@counter = 0
  def CodeWrapper.enter; @@counter += 1; end
  def CodeWrapper.leave; @@counter += 1; end
  def CodeWrapper.counter; @@counter; end
end

class T2; def m; end; end

class TestAspectR < Test::Unit::TestCase
  # Just so that we can use previously written tests. Clean up when there is
  # time!
  @@logger = Logger.new(@@hso = HistoryStdOut.new)
  @@counter = Counter.new
  @@t, @@u = TestHello.new, TestHello.new

  def setup
  end

  def test_01_wrap
    @@counter.wrap(TestHello, :say) # Wrap counter on TestHello#say
    assert_equal('hello world', @@t.say('hello'))
    assert_equal('hello world', @@u.say('hello'))
    assert_equal(1, @@counter[@@t, :say])
    assert_equal(1, @@counter[@@u, :say])
    @@t.say("my")
    assert_equal(2, @@counter[@@t, :say])
    assert_equal(1, @@counter[@@u, :say])
  end

  def test_02_class_wrapping
    @@logger.wrap(TestHello, :enter, :exit, /sa/)
    @@t.say('t: hello')
    assert_match(/enter.*TestHello#say: called with \[.*\]/, @@hso.history[-2] )
    assert_match(/exit.*TestHello#say: exited/, @@hso.history[-1] )
    @@u.say('u: hello')
    assert_match(/enter.*TestHello#say: called with \[.*\]/,@@hso.history[-2])
    assert_match(/exit.*TestHello#say: exited/,@@hso.history[-1])
  end

  def test_03_singleton_wrapping
    @@logger.wrap(@@t, :senter, :sexit, :say)
    @@t.say('t: hello')
    assert_match( /senter/, @@hso.history[-4])
    assert_match( /enter/,  @@hso.history[-3])
    assert_match( /exit/,   @@hso.history[-2])
    assert_match(/sexit/,   @@hso.history[-1])
    @@u.say('u: hello')
    assert_match( /enter/,  @@hso.history[-2])
    assert_match(/exit/,    @@hso.history[-1])
  end

  def test_04_unwrapping
    @@logger.unwrap(TestHello, :enter, :exit, /sa/)
    @@t.say('t: hello') # senter and sexit should still be there...
    assert_match(/senter/, @@hso.history[-2])
    assert_match(/sexit/,  @@hso.history[-1])
    l = @@hso.history.length
    @@u.say('u: hello')
    assert_equal(l, @@hso.history.length) # Nothing printed!
  end

  def test_05_dynamically_changing_advice
    Logger.class_eval <<-'EOC'
      def senter(*args)
	@io.puts "senter version 2.0"
      end
    EOC
    @@t.say('t: hello')
    assert_match(/senter version 2\.0/, @@hso.history[-2])
  end

  def test_06_partial_unwrap
    @@logger.unwrap(@@t, :senter, nil, :say)
    l = @@hso.history.length
    @@t.say('t: hello') # Should use sexit but not senter
    assert_equal(l+1, @@hso.history.length)
    assert_match(/sexit/, @@hso.history[-1])
  end

  def test_07_exception_in_method
    @@logger.wrap(@@t, nil, :exit, :sayz)
    l = @@hso.history.length
    begin
      @@t.sayz 1
    rescue Exception; end
    assert_equal(l+1, @@hso.history.length)
    assert_match(/exit/, @@hso.history[-1])
  end

  def test_08_counter
    assert_equal(7, @@counter[@@t, :say])
    @@counter.unwrap(TestHello, :say) 
    @@t.say('t: hello')
    assert_equal(7, @@counter[@@t, :say])
  end

  def test_09_transparency
    assert_equal(1, TestHello.instance_method(:say).arity)
    assert_equal(-1, TestHello.instance_method(:sayz).arity)

    @@counter.wrap(TestHello, :tt)
    assert_equal(0, TestHello.instance_method(:tt).arity)
  end

  def test_10_special_methods
    @@logger.wrap(Array, :enter, nil, :[], :[]=, :initialize)
    a = Array.new(2)
    assert_match(/enter/, @@hso.history.last); l = @@hso.history.length
    a[1]
    assert_equal(l+1, @@hso.history.length)
    assert_match(/enter/, @@hso.history.last); l = @@hso.history.length
    a[1] = 10
    assert_equal(l+1, @@hso.history.length)
    assert_match(/enter/, @@hso.history.last); l = @@hso.history.length
    @@logger.unwrap(Array, :[], :[]=, :initialize)
  end

  def test_11_code_wrapping  
    assert_equal(0, CodeWrapper.counter)
    CodeWrapper.new.code_wrap(T2, :m)
    T2.new.m
    assert_equal(2, CodeWrapper.counter)
  end
end


class T3; def m; end; def m2; end; end

def time(n = 100_000, &block)
  start = Process.times.utime
  n.times{block.call}
  Process.times.utime - start
end

def test_overhead
  puts "\nOverhead"
  t = T3.new
  puts "Time for unwrapped: #{tuw = time(50_000) {t.m}}"
  CodeWrapper.new.code_wrap(T3, :m)
  puts "Time for code-wrapped: #{tw = time(50_000) {t.m}}"
  puts "A slowdown of #{tw/tuw}"
end