From 08c2d0b3bce1432b03566ad0e4a5c984bcc8c074 Mon Sep 17 00:00:00 2001 From: Mike Blumtritt Date: Tue, 18 Jun 2024 06:39:50 +0000 Subject: [PATCH] v1.2.0 (#6) - support to print `Thread` and `Fiber` variables with `.vars` - using `STDERR` by default - require `#<<` for output stream - `.trace_results` is enabled by default - add `.traced?` function to test whether an object is traced - extend tests and examples - correct help text - bump version to v1.2.0 Fibers are not supported on all platforms! Method trace for methods declared via `attr_xxx` are not supported in Ruby v3.0 (but later)! --- README.md | 65 ++--- examples/foo.rb | 51 ++-- examples/kernel_calls.rb | 1 - lib/im-lost.rb | 369 +++++++++++++++++---------- lib/im-lost/version.rb | 2 +- spec/helper.rb | 2 +- spec/lib/im-lost_spec.rb | 531 +++++++++++++++++++++++---------------- spec/support/matcher.rb | 32 +++ 8 files changed, 652 insertions(+), 401 deletions(-) create mode 100644 spec/support/matcher.rb diff --git a/README.md b/README.md index e344541..6255f00 100644 --- a/README.md +++ b/README.md @@ -22,13 +22,13 @@ end # output will look like # > IO#<<(?) -# /projects/test.rb:1 +# /examples/test.rb:1 # > IO#write(*) -# /projects/test.rb:1 +# /examples/test.rb:1 # > IO#puts(*) -# /projects/test.rb:2 +# /examples/test.rb:2 # > IO#write(*) -# /projects/test.rb:2 +# /examples/test.rb:2 ``` When you need to know if exceptions are raised and handled you can use `ImLost.trace_exceptions`: @@ -42,11 +42,11 @@ end # output will look like # x Errno::EEXIST: File exists @ rb_sysopen - / -# /projects/test.rb:2 +# /examples/test.rb:2 # ! Errno::EEXIST: File exists @ rb_sysopen - / -# /projects/test.rb:3 +# /examples/test.rb:3 # x RuntimeError: something went wrong! -# /projects/test.rb:4 +# /examples/test.rb:4 ``` When you like to know if a code point is reached, `ImLost.here` will help: @@ -94,7 +94,6 @@ class Foo def bar = :bar end -ImLost.trace_results = true ImLost.trace(Foo) my_foo = Foo.create(value: :foo!) @@ -111,47 +110,55 @@ ImLost.vars(my_foo) # output will look like # > Foo.create(:foo!) -# /projects/foo.rb:25 +# /examples/foo.rb:24 # > Foo.new(*) -# /projects/foo.rb:6 +# /examples/foo.rb:6 # < Foo.new(*) -# = # +# /examples/foo.rb:6 +# = # # < Foo.create(:foo!) -# = # +# /examples/foo.rb:24 +# = # # > Foo#foo(1, *[], :none, **{}, &nil) -# /projects/foo.rb:28 +# /examples/foo.rb:27 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # < Foo#foo(1, *[], :none, **{}, &nil) +# /examples/foo.rb:27 # = "1-none-[]-{}-bar" -# = /projects/foo.rb:29 -# instance variables: -# @value: "1-none-[]-{}-bar" +# * /examples/foo.rb:28 +# > instance variables +# @value: "1-none-[]-{}-bar" # > Foo#foo(2, *[:a, :b, :c], :some, **{:name=>:value}, &nil) -# /projects/foo.rb:31 +# /examples/foo.rb:30 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # < Foo#foo(2, *[:a, :b, :c], :some, **{:name=>:value}, &nil) +# /examples/foo.rb:30 # = "2-some-[a,b,c]-{:name=>:value}-bar" -# = /projects/foo.rb:32 -# instance variables: -# @value: "2-some-[a,b,c]-{:name=>:value}-bar" -# > Foo#foo(3, *[], nil, **{}, &#) -# /projects/foo.rb:34 +# * /examples/foo.rb:31 +# > instance variables +# @value: "2-some-[a,b,c]-{:name=>:value}-bar" +# > Foo#foo(3, *[], nil, **{}, &#) +# /examples/foo.rb:33 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # 3--[]-{}-bar -# < Foo#foo(3, *[], nil, **{}, &#) +# < Foo#foo(3, *[], nil, **{}, &#) +# /examples/foo.rb:33 # = nil -# = /projects/foo.rb:35 -# instance variables: -# @value: "3--[]-{}-bar" +# * /examples/foo.rb:34 +# > instance variables +# @value: "3--[]-{}-bar" ``` See [examples dir](./examples) for more… diff --git a/examples/foo.rb b/examples/foo.rb index ac21211..7cc7933 100644 --- a/examples/foo.rb +++ b/examples/foo.rb @@ -19,7 +19,6 @@ def foo(arg, *args, key: nil, **kw_args, &block) def bar = :bar end -ImLost.trace_results = true ImLost.trace(Foo) my_foo = Foo.create(value: :foo!) @@ -36,44 +35,52 @@ def bar = :bar # output will look like # > Foo.create(:foo!) -# /projects/foo.rb:25 +# /examples/foo.rb:24 # > Foo.new(*) -# /projects/foo.rb:6 +# /examples/foo.rb:6 # < Foo.new(*) -# = # +# /examples/foo.rb:6 +# = # # < Foo.create(:foo!) -# = # +# /examples/foo.rb:24 +# = # # > Foo#foo(1, *[], :none, **{}, &nil) -# /projects/foo.rb:28 +# /examples/foo.rb:27 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # < Foo#foo(1, *[], :none, **{}, &nil) +# /examples/foo.rb:27 # = "1-none-[]-{}-bar" -# = /projects/foo.rb:29 -# instance variables: -# @value: "1-none-[]-{}-bar" +# * /examples/foo.rb:28 +# > instance variables +# @value: "1-none-[]-{}-bar" # > Foo#foo(2, *[:a, :b, :c], :some, **{:name=>:value}, &nil) -# /projects/foo.rb:31 +# /examples/foo.rb:30 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # < Foo#foo(2, *[:a, :b, :c], :some, **{:name=>:value}, &nil) +# /examples/foo.rb:30 # = "2-some-[a,b,c]-{:name=>:value}-bar" -# = /projects/foo.rb:32 -# instance variables: -# @value: "2-some-[a,b,c]-{:name=>:value}-bar" -# > Foo#foo(3, *[], nil, **{}, &#) -# /projects/foo.rb:34 +# * /examples/foo.rb:31 +# > instance variables +# @value: "2-some-[a,b,c]-{:name=>:value}-bar" +# > Foo#foo(3, *[], nil, **{}, &#) +# /examples/foo.rb:33 # > Foo#bar() -# /projects/foo.rb:15 +# /examples/foo.rb:15 # < Foo#bar() +# /examples/foo.rb:15 # = :bar # 3--[]-{}-bar -# < Foo#foo(3, *[], nil, **{}, &#) +# < Foo#foo(3, *[], nil, **{}, &#) +# /examples/foo.rb:33 # = nil -# = /projects/foo.rb:35 -# instance variables: -# @value: "3--[]-{}-bar" +# * /examples/foo.rb:34 +# > instance variables +# @value: "3--[]-{}-bar" diff --git a/examples/kernel_calls.rb b/examples/kernel_calls.rb index 26ab92a..e99cf01 100644 --- a/examples/kernel_calls.rb +++ b/examples/kernel_calls.rb @@ -9,7 +9,6 @@ require 'im-lost' -ImLost.trace_results = true ImLost.trace(Kernel, Object, Module, Class, self) do puts '=' * 79 pp Class.new diff --git a/lib/im-lost.rb b/lib/im-lost.rb index 3806d2c..d946957 100644 --- a/lib/im-lost.rb +++ b/lib/im-lost.rb @@ -26,9 +26,10 @@ def caller_locations=(value) # # The output device used to write information. - # This should be an `IO` device or any other object responding to `#puts`. + # This should be an `IO` device or any other object responding to `#<<` + # like a Logger. # - # `$stderr` is configured by default. + # `STDERR` is configured by default. # # @example Write to a file # ImLost.output = File.new('./trace', 'w') @@ -50,8 +51,13 @@ def caller_locations=(value) attr_reader :output def output=(value) - return @output = value if value.respond_to?(:puts) - raise(ArgumentError, "invalid output device - #{value.inspect}") + return @output = value if defined?(value.<<) + raise( + NoMethodError, + "undefined method `<<' for an instance of #{ + Kernel.instance_method(:class).bind(value).call + }" + ) end # @@ -89,11 +95,11 @@ def trace_calls=(value) # # # output will look like # # x Errno::EEXIST: File exists @ rb_sysopen - / - # # /projects/test.rb:2 + # # /examples/test.rb:2 # # ! Errno::EEXIST: File exists @ rb_sysopen - / - # # /projects/test.rb:3 + # # /examples/test.rb:3 # # x RuntimeError: something went wrong! - # # /projects/test.rb:4 + # # /examples/test.rb:4 # # @param with_locations [Boolean] wheter the locations should be included # into the exception trace information @@ -113,7 +119,7 @@ def trace_exceptions(with_locations: true) # # Enables/disables tracing of returned valuess of method calls. - # This is disabled by default. + # This is enabled by default. # # @attribute [r] trace_results # @return [Boolean] whether return values will be traced @@ -131,33 +137,33 @@ def trace_results=(value) # # Print the call location conditionally. # - # @example simply print location + # @example Print current location # ImLost.here # - # @example print location when instance variable is empty + # @example Print current location when instance variable is empty # ImLost.here(@name.empty?) # - # @example print location when instance variable is nil or empty + # @example Print current location when instance variable is nil or empty # ImLost.here { @name.nil? || @name.empty? } # # @overload here - # Prints the caller location. + # Prints the call location. # @return [true] # # @overload here(test) - # Prints the caller location when given argument is truthy. + # Prints the call location when given argument is truthy. # @param test [Object] # @return [Object] test # # @overload here - # Prints the caller location when given block returns a truthy result. + # Prints the call location when given block returns a truthy result. # @yield When the block returns a truthy result the location will be print # @yieldreturn [Object] return result # def here(test = true) return test if !test || (block_given? && !(test = yield)) loc = Kernel.caller_locations(1, 1)[0] - @output.puts(": #{loc.path}:#{loc.lineno}") + @output << "* #{loc.path}:#{loc.lineno}\n" test end @@ -166,12 +172,12 @@ def here(test = true) # # The given arguments can be any object instance or module or class. # - # @example trace method calls of an instance variable for a while + # @example Trace method calls of an instance variable for a while # ImLost.trace(@file) # # ... # ImLost.untrace(@file) # - # @example temporary trace method calls + # @example Temporary trace method calls # File.open('test.txt', 'w') do |file| # ImLost.trace(file) do # file << 'hello ' @@ -181,17 +187,17 @@ def here(test = true) # # # output will look like # # > IO#<<(?) - # # /projects/test.rb:1 + # # /examples/test.rb:1 # # > IO#write(*) - # # /projects/test.rb:1 + # # /examples/test.rb:1 # # > IO#puts(*) - # # /projects/test.rb:2 + # # /examples/test.rb:2 # # > IO#write(*) - # # /projects/test.rb:2 + # # /examples/test.rb:2 # # @overload trace(*args) # @param args [[Object]] one or more objects to be traced - # @return [[Object]] the traced object(s) + # @return [Array] the traced object(s) # Start tracing the given objects. # @see untrace # @see untrace_all! @@ -209,30 +215,37 @@ def trace(*args, &block) args.size == 1 ? _trace_b(args[0], &block) : _trace_all_b(args, &block) end + # + # Test if a given object is currently traced. + # + # @param arg [Object] object to be tested + # @return [Boolean] wheter the object is beeing traced + # + def traced?(obj) = @trace.key?(obj) + # # Stop tracing objects. # - # @example trace some objects for some code lines - # traced_vars = ImLost.trace(@file, @client) + # @example Trace some objects for some code lines + # traced_obj = ImLost.trace(@file, @client) # # ... - # ImLost.untrace(*traced_vars) + # ImLost.untrace(*traced_obj) # # @see trace # - # @param args [[Object]] one or more objects which should not longer be + # @param args [[]Object]] one or more objects which should not longer be # traced - # @return [[Object]] the object(s) which are not longer be traced + # @return [Array] the object(s) which are not longer be traced # @return [nil] when none of the objects was traced before # def untrace(*args) - ret = args.filter_map { @trace.delete(_1.__id__) ? _1 : nil } - args.size == 1 ? ret[0] : ret + args = args.filter_map { @trace.delete(_1) } + args.size < 2 ? args[0] : args end # - # Stop tracing any object. - # (When you are really lost and just like to stop tracing of all your - # objects.) + # Stop tracing any object. When you are really lost and just like to stop + # tracing of all your objects. # # @see trace # @@ -244,101 +257,147 @@ def untrace_all! end # - # Inspect internal variables. + # Inspect internal variables of a given object. + # + # @note The dedictaed handling of `Fiber` is platform dependend! + # + # @example Inspect current instance variables + # @a = 22 + # b = 20 + # c = @a + b + # ImLost.vars(self) + # # => print value of `@a` + # + # @example Inspect local variables + # @a = 22 + # b = 20 + # c = @a + b + # ImLost.vars(binding) + # # => print values of `b` and 'c' + # + # @example Inspect a thread's variables + # th = Thread.new { th[:var1] += 20 } + # th[:var1] = 22 + # ImLost.vars(th) + # # => print value of `var1` + # th.join + # ImLost.vars(th) + # + # @example Inspect the current fiber's storage + # Fiber[:var1] = 22 + # Fiber[:var2] = 20 + # Fiber[:var3] = Fiber[:var1] + Fiber[:var2] + # ImLost.vars(Fiber.current) + # + # When the given object is + # + # - a `Binding` it prints the local variables of the binding + # - a `Thread` it prints the fiber-local and thread variables + # - the current `Fiber` it prints the fibers' storage # - # @overload vars(binding) - # Inspect local variables of given Binding. - # @param binding [Binding] which local variables should be print - # @return [self] itself + # Be aware that only the current fiber can be inspected. # - # @overload vars(object) - # Inspect instance variables of given object. - # @param object [Object] which instance variables should be print - # @return [Object] the given object + # When the given object can not be inspected it prints an error message. + # + # @param object [Object] which instance variables should be print + # @return [Object] the given object # def vars(object) - traced = @trace.delete(object.__id__) - return _local_vars(object) if object.is_a?(Binding) - return unless object.respond_to?(:instance_variables) - _vars(object, Kernel.caller_locations(1, 1)[0]) + out = Out.new + traced = @trace.delete(object) + return _local_vars(out, object) if Binding === object + location = Kernel.caller_locations(1, 1)[0] + out << "* #{location.path}:#{location.lineno}" + return _thread_vars(out, object) if Thread === object + return _fiber_vars(out, object) if @fiber_supported && Fiber === object + return _instance_vars(out, object) if defined?(object.instance_variables) + out << ' !!! unable to retrieve vars' + object ensure @trace[traced] = traced if traced + out.flush(@output) end private - def as_sig(prefix, info, args) - args = args.join(', ') - case info.self - when Class, Module - "#{prefix} #{info.self}.#{info.method_id}(#{args})" - else - "#{prefix} #{info.defined_class}##{info.method_id}(#{args})" - end + def _can_trace?(arg) + (id = arg.__id__) != __id__ && id != @output.__id__ end def _trace(arg) - id = arg.__id__ - @trace[id] = id if __id__ != id && @output.__id__ != id + @trace[arg] = arg if _can_trace?(arg) arg end def _trace_all(args) - args.each do |arg| - arg = arg.__id__ - @trace[arg] = arg if __id__ != arg && @output.__id__ != arg - end + args.each { |arg| @trace[arg] = arg if _can_trace?(arg) } args end def _trace_b(arg) - id = arg.__id__ - return yield(arg) if __id__ == id || @output.__id__ == id + return yield(arg) if @trace.key?(arg) || !_can_trace?(arg) begin - @trace[id] = id + @trace[arg] = arg yield(arg) ensure - @trace.delete(id) if id + @trace.delete(arg) end end def _trace_all_b(args) - ids = + temp = args.filter_map do |arg| - arg = arg.__id__ - @trace[arg] = arg if __id__ != arg && @output.__id__ != arg + @trace[arg] = arg if !@trace.key?(arg) && _can_trace?(arg) end yield(args) ensure - ids.each { @trace.delete(_1) } + temp.each { @trace.delete(_1) } end - def _vars(obj, location) - @output.puts("= #{location.path}:#{location.lineno}") - vars = obj.instance_variables - if vars.empty? - @output.puts(' ') - return obj + def _local_vars(out, binding) + out << "* #{binding.source_location.join(':')}" + out.vars('local variables', binding.local_variables) do |name| + binding.local_variable_get(name) end - @output.puts(' instance variables:') - vars.sort!.each do |name| - @output.puts(" #{name}: #{obj.instance_variable_get(name).inspect}") + binding + end + + def _thread_vars(out, thread) + out << " #{_thread_identifier(thread)}" + flv = thread.keys + out.vars('fiber-local variables', flv) { thread[_1] } unless flv.empty? + out.vars('thread variables', thread.thread_variables) do |name| + thread.thread_variable_get(name) end - obj + thread end - def _local_vars(binding) - @output.puts("= #{binding.source_location.join(':')}") - vars = binding.local_variables - if vars.empty? - @output.puts(' ') - return self + def _fiber_vars(out, fiber) + if Fiber.current == fiber + storage = fiber.storage || {} + out.vars('fiber storage', storage.keys) { storage[_1] } + else + out << ' !!! given Fiber is not the current Fiber' << + " #{fiber.inspect}" end - @output.puts(' local variables:') - vars.sort!.each do |name| - @output.puts(" #{name}: #{binding.local_variable_get(name).inspect}") + fiber + end + + def _instance_vars(out, object) + out.vars('instance variables', object.instance_variables) do |n| + object.instance_variable_get(n) end - self + object + end + + def _thread_identifier(thread) + "#{THREAD_STATE[thread.status] || thread.status} Thread #{ + if defined?(thread.native_thread_id) + thread.native_thread_id + else + thread.__id__ + end + } #{thread.name}".rstrip end end @@ -365,7 +424,7 @@ def _local_vars(binding) # # the timer with name 'my_test' is not longer valid now # # - # @example Use an anonymous timer (identified by ID) + # @example Use an anonymous timer # tmr = ImLost.timer.create # # # ...your code here... @@ -440,7 +499,7 @@ def delete(*id_or_names) end # - # Print the ID or name and the runtime since timer was created. + # Print the ID or name and the runtime since a timer was created. # It includes the location. # # @param id_or_name [Integer, #to_s] the identifier or the name of the timer @@ -476,80 +535,118 @@ def initialize(&block) end end + class Out + def initialize(*lines) = (@lines = lines) + def <<(str) = @lines << str + def location(loc) = @lines << " #{loc.path}:#{loc.lineno}" + def flush(dev) = dev << (@lines << nil).join("\n") + + def sig(prefix, info, args) + args = args.join(', ') + @lines << case info.self + when Class, Module + "#{prefix} #{info.self}.#{info.method_id}(#{args})" + else + "#{prefix} #{info.defined_class}##{info.method_id}(#{args})" + end + end + + def vars(kind, names) + return @lines << " " if names.empty? + @lines << " > #{kind}" + names.sort!.each { @lines << " #{_1}: #{yield(_1).inspect}" } + end + end + private_constant :Out + ARG_SIG = { rest: '*', keyrest: '**', block: '&' }.compare_by_identity.freeze NO_NAME = { :* => 1, :** => 1, :& => 1 }.compare_by_identity.freeze - private_constant :ARG_SIG, :NO_NAME + THREAD_STATE = { + false => 'terminated', + nil => 'aborted' + }.compare_by_identity.freeze + private_constant :ARG_SIG, :NO_NAME, :THREAD_STATE @trace = {}.compare_by_identity - @caller_locations = true - @output = $stderr.respond_to?(:puts) ? $stderr : STDERR - - @timer = - TimerStore.new do |title, location, time| - @output.puts( - "T #{title}: #{time ? "#{time} sec." : 'created'}", - " #{location.path}:#{location.lineno}" - ) - end + @caller_locations = @exception_locations = true + @output = STDERR + + @timer = TimerStore.new { |title, location, time| @output << <<~TIMER_MSG } + T #{title}: #{time ? "#{time} sec." : 'created'} + #{location.path}:#{location.lineno} + TIMER_MSG TimerStore.private_class_method(:new) @trace_calls = [ TracePoint.new(:c_call) do |tp| - next if !@trace.key?(tp.self.__id__) || tp.path == __FILE__ - @output.puts(as_sig('>', tp, tp.parameters.map { ARG_SIG[_1[0]] || '?' })) - @output.puts(" #{tp.path}:#{tp.lineno}") if @caller_locations + next if !@trace.key?(tp.self) || tp.path == __FILE__ + out = Out.new + out.sig('>', tp, tp.parameters.map { ARG_SIG[_1[0]] || '?' }) + out.location(tp) if @caller_locations + out.flush(@output) end, TracePoint.new(:call) do |tp| - next if !@trace.key?(tp.self.__id__) || tp.path == __FILE__ + next if !@trace.key?(tp.self) || tp.path == __FILE__ ctx = tp.binding - @output.puts( - as_sig( - '>', - tp, - tp.parameters.map do |kind, name| - next name if NO_NAME.key?(name) - "#{ARG_SIG[kind]}#{ctx.local_variable_get(name).inspect}" - end - ) + out = Out.new + out.sig( + '>', + tp, + tp.parameters.map do |kind, name| + next name if NO_NAME.key?(name) + "#{ARG_SIG[kind]}#{ctx.local_variable_get(name).inspect}" + end ) - next unless @caller_locations - loc = ctx.eval('caller_locations(4,1)')[0] - @output.puts(" #{loc.path}:#{loc.lineno}") + out.location(ctx.eval('caller_locations(4,1)')[0]) if @caller_locations + out.flush(@output) end ] @trace_results = [ TracePoint.new(:c_return) do |tp| - next if !@trace.key?(tp.self.__id__) || tp.path == __FILE__ - @output.puts(as_sig('<', tp, tp.parameters.map { ARG_SIG[_1[0]] || '?' })) - @output.puts(" = #{tp.return_value.inspect}") + next if !@trace.key?(tp.self) || tp.path == __FILE__ + out = Out.new + out.sig('<', tp, tp.parameters.map { ARG_SIG[_1[0]] || '?' }) + out.location(tp) if @caller_locations + out << " = #{tp.return_value.inspect}" + out.flush(@output) end, TracePoint.new(:return) do |tp| - next if !@trace.key?(tp.self.__id__) || tp.path == __FILE__ + next if !@trace.key?(tp.self) || tp.path == __FILE__ ctx = tp.binding - @output.puts( - as_sig( - '<', - tp, - tp.parameters.map do |kind, name| - next name if NO_NAME.key?(name) - "#{ARG_SIG[kind]}#{ctx.local_variable_get(name).inspect}" - end - ) + out = Out.new + out.sig( + '<', + tp, + tp.parameters.map do |kind, name| + next name if NO_NAME.key?(name) + "#{ARG_SIG[kind]}#{ctx.local_variable_get(name).inspect}" + end ) - @output.puts(" = #{tp.return_value.inspect}") + out.location(ctx.eval('caller_locations(4,1)')[0]) if @caller_locations + out << " = #{tp.return_value.inspect}" + out.flush(@output) end ] supported = RUBY_VERSION.to_f < 3.3 ? %i[raise] : %i[raise rescue] @trace_exceptions = TracePoint.new(*supported) do |tp| - ex = tp.raised_exception.inspect - @output.puts( - "#{tp.event == :raise ? 'x' : '!'} #{ex[0] == '#' ? ex[2..-2] : ex}" - ) - @output.puts(" #{tp.path}:#{tp.lineno}") if @exception_locations + ex = tp.raised_exception + mark, parent = tp.event == :rescue ? ['!', ex.cause] : 'x' + ex = ex.inspect + out = Out.new("#{mark} #{ex[0] == '#' ? ex[2..-2] : ex}") + while parent + ex = parent.inspect + out << " [#{ex[0] == '#' ? ex[2..-2] : ex}]" + parent = parent.cause + end + out.location(tp) if @exception_locations + out.flush(@output) end - self.trace_calls = true + @fiber_supported = + !!(defined?(Fiber.current) && defined?(Fiber.current.storage)) + + self.trace_calls = self.trace_results = true end diff --git a/lib/im-lost/version.rb b/lib/im-lost/version.rb index a472847..d65fcd7 100644 --- a/lib/im-lost/version.rb +++ b/lib/im-lost/version.rb @@ -2,5 +2,5 @@ module ImLost # The version number of the gem. - VERSION = '1.1.0' + VERSION = '1.2.0' end diff --git a/spec/helper.rb b/spec/helper.rb index 5d85f55..3d2a2b5 100644 --- a/spec/helper.rb +++ b/spec/helper.rb @@ -4,7 +4,7 @@ RSpec.configure(&:disable_monkey_patching!) -require 'stringio' +require_relative 'support/matcher' RE_FLOAT = '[-+]?[0-9]*\.?[0-9]+([eE][-+]?[0-9]+)?' diff --git a/spec/lib/im-lost_spec.rb b/spec/lib/im-lost_spec.rb index 9f7583a..21dc2c7 100644 --- a/spec/lib/im-lost_spec.rb +++ b/spec/lib/im-lost_spec.rb @@ -2,37 +2,35 @@ class TestSample def initialize - @state = :created + @foo = 20 + @bar = 22 end - def add(arg0, arg1) - @result = arg0 + arg1 + if RUBY_VERSION.to_f <= 3.0 + # there is a bug in Ruby 3.0 which does not allow to trace + # methods declared with attr_xxx + def foo = @foo + def bar = @bar + else + attr_reader :foo, :bar end - def add_kw(arg0:, arg1:) - @result = arg0 + arg1 - end - - def add_block(arg0, &block) = add(arg0, block&.call || 42) + def add(arg0, arg1) = arg0 + arg1 + def add_kw(arg0:, arg1:) = arg0 + arg1 + def add_block(arg, &block) = arg + block[] def map(*args) = args.map(&:to_s) def insp(**kw_args) = kw_args.inspect def fwd(...) = add(...) - def foo = :foo - def bar = :bar end RSpec.describe ImLost do let(:sample) { TestSample.new } - let(:output) { ImLost.output.string } - - before { ImLost.output = StringIO.new } - after { ImLost.untrace_all! } it 'has defined default attributes' do is_expected.to have_attributes( caller_locations: true, trace_calls: true, - trace_results: false + trace_results: true ) end @@ -44,96 +42,97 @@ def bar = :bar ImLost.trace(sample) end - it 'traces method calls' do - sample.foo - sample.bar + after { ImLost.untrace_all! } - expect(output).to eq "> TestSample#foo()\n> TestSample#bar()\n" + it 'traces method calls' do + expect { sample.foo + sample.bar }.to write <<~OUTPUT + > TestSample#foo() + > TestSample#bar() + OUTPUT end it 'includes arguments in call signatures' do - sample.add(21, 21) - - expect(output).to eq "> TestSample#add(21, 21)\n" + expect { sample.add(21, 21) }.to write "> TestSample#add(21, 21)\n" end it 'includes keyword arguments in call signatures' do - sample.add_kw(arg0: 21, arg1: 21) - - expect(output).to eq "> TestSample#add_kw(21, 21)\n" + expect { sample.add_kw(arg0: 21, arg1: 21) }.to write( + "> TestSample#add_kw(21, 21)\n" + ) end it 'includes block arguments in call signatures' do - block = proc { 42 } - sample.add_block(21, &block) - - expect(output).to eq <<~OUTPUT - > TestSample#add_block(21, &#{block.inspect}) - > TestSample#add(21, 42) - OUTPUT + block = proc { 22 } + expect { sample.add_block(20, &block) }.to write( + "> TestSample#add_block(20, &#{block.inspect})\n" + ) end it 'includes splat arguments' do - sample.map(1, 2, 3, 4) - - expect(output).to eq "> TestSample#map(*[1, 2, 3, 4])\n" + expect { sample.map(1, 2, 3, 4) }.to write( + "> TestSample#map(*[1, 2, 3, 4])\n" + ) end it 'includes empty splat arguments' do - sample.map - - expect(output).to eq "> TestSample#map(*[])\n" + expect { sample.map }.to write "> TestSample#map(*[])\n" end it 'includes keyword splat arguments' do - sample.insp(a: 1, b: 2) - - expect(output).to eq "> TestSample#insp(**{:a=>1, :b=>2})\n" + expect { sample.insp(a: 1, b: 2) }.to write( + "> TestSample#insp(**{:a=>1, :b=>2})\n" + ) end it 'includes empty keyword splat arguments' do - sample.insp - - expect(output).to eq "> TestSample#insp(**{})\n" + expect { sample.insp }.to write "> TestSample#insp(**{})\n" end it 'handles argument forwarding' do - sample.fwd(40, 2) + expected = + if RUBY_VERSION.to_f < 3.1 + <<~OUTPUT + > TestSample#fwd(*, &) + > TestSample#add(40, 2) + OUTPUT + else + <<~OUTPUT + > TestSample#fwd(*, **, &) + > TestSample#add(40, 2) + OUTPUT + end - if RUBY_VERSION.to_f < 3.1 - expect(output).to eq <<~OUTPUT - > TestSample#fwd(*, &) - > TestSample#add(40, 2) - OUTPUT - else - expect(output).to eq <<~OUTPUT - > TestSample#fwd(*, **, &) - > TestSample#add(40, 2) - OUTPUT - end + expect { sample.fwd(40, 2) }.to write expected + end + + it 'can check if an object is traced' do + expect(ImLost.traced?(sample)).to be true + expect(ImLost.untrace(sample)).to be sample + expect(ImLost.traced?(sample)).to be false + expect(ImLost.traced?(BasicObject.new)).to be false end - it 'can trace an object in a block only' do - example = TestSample.new - example.foo - ImLost.trace(example) { |obj| obj.add(20, 22) } - example.foo + it 'can trace temporary' do + another = TestSample.new - expect(output).to eq "> TestSample#add(20, 22)\n" + expect do + another.map + ImLost.trace(another) { |obj| obj.add(20, 22) } + another.map + end.to write "> TestSample#add(20, 22)\n" end it 'can include caller locations' do ImLost.caller_locations = true - sample.foo - expect(output).to eq <<~OUTPUT - > TestSample#foo() - #{__FILE__}:#{__LINE__ - 4} + expect { sample.add(1, 1) }.to write <<~OUTPUT + > TestSample#add(1, 1) + #{__FILE__}:#{__LINE__ - 2} OUTPUT end end - context 'trace method call results' do + context 'trace method results' do before do ImLost.trace_calls = false ImLost.caller_locations = false @@ -141,172 +140,202 @@ def bar = :bar ImLost.trace(sample) end - it 'traces method call results' do - sample.foo - sample.bar + after { ImLost.untrace_all! } - expect(output).to eq <<~OUTPUT + it 'traces method call results' do + expect { sample.foo + sample.bar }.to write <<~OUTPUT < TestSample#foo() - = :foo + = 20 < TestSample#bar() - = :bar + = 22 OUTPUT end it 'includes arguments in call signatures' do - sample.add(21, 21) - - expect(output).to eq "< TestSample#add(21, 21)\n = 42\n" + expect { sample.add(21, 21) }.to write( + "< TestSample#add(21, 21)\n = 42\n" + ) end it 'includes block arguments in call signatures' do - block = proc { 42 } - sample.add_block(21, &block) - - expect(output).to eq <<~OUTPUT - < TestSample#add(21, 42) - = 63 - < TestSample#add_block(21, &#{block.inspect}) - = 63 + block = proc { 20 } + + expect { sample.add_block(22, &block) }.to write <<~OUTPUT + < TestSample#add_block(22, &#{block.inspect}) + = 42 OUTPUT end it 'includes splat arguments' do - sample.map(1, 2, 3, 4) - - expect(output).to eq <<~OUTPUT + expect { sample.map(1, 2, 3, 4) }.to write <<~OUTPUT < TestSample#map(*[1, 2, 3, 4]) = ["1", "2", "3", "4"] OUTPUT end it 'includes empty splat arguments' do - sample.map - expect(output).to eq "< TestSample#map(*[])\n = []\n" + expect { sample.map }.to write "< TestSample#map(*[])\n = []\n" end it 'includes keyword splat arguments' do - sample.insp(a: 1, b: 2) - - expect(output).to eq <<~OUTPUT + expect { sample.insp(a: 1, b: 2) }.to write <<~OUTPUT < TestSample#insp(**{:a=>1, :b=>2}) = "{:a=>1, :b=>2}" OUTPUT end it 'includes empty keyword splat arguments' do - sample.insp - - expect(output).to eq "< TestSample#insp(**{})\n = \"{}\"\n" + expect { sample.insp }.to write "< TestSample#insp(**{})\n = \"{}\"\n" end it 'handles argument forwarding' do - sample.fwd(40, 2) - - if RUBY_VERSION.to_f < 3.1 - expect(output).to eq <<~OUTPUT - < TestSample#add(40, 2) - = 42 - < TestSample#fwd(*, &) - = 42 - OUTPUT - else - expect(output).to eq <<~OUTPUT - < TestSample#add(40, 2) - = 42 - < TestSample#fwd(*, **, &) - = 42 - OUTPUT - end + expected = + if RUBY_VERSION.to_f < 3.1 + <<~OUTPUT + < TestSample#add(40, 2) + = 42 + < TestSample#fwd(*, &) + = 42 + OUTPUT + else + <<~OUTPUT + < TestSample#add(40, 2) + = 42 + < TestSample#fwd(*, **, &) + = 42 + OUTPUT + end + + expect { sample.fwd(40, 2) }.to write expected end - it 'can trace an object`s call results in a block only' do - example = TestSample.new - example.foo - ImLost.trace(example) { |obj| obj.add(20, 22) } - example.foo + it 'can trace temporary' do + another = TestSample.new - expect(output).to eq "< TestSample#add(20, 22)\n = 42\n" + expect do + another.map + ImLost.trace(another) { |obj| obj.add(20, 22) } + another.map + end.to write "< TestSample#add(20, 22)\n = 42\n" end end context '.trace_exceptions' do it 'traces exceptions and rescue blocks' do - raise_location = "#{__FILE__}:#{__LINE__ + 4}" - rescue_location = "#{__FILE__}:#{__LINE__ + 4}" - - ImLost.trace_exceptions do - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - if RUBY_VERSION.to_f < 3.3 - expect(output).to eq <<~OUTPUT + expect do + ImLost.trace_exceptions do + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + end.to write <<~OUTPUT x ArgumentError: not the answer - 21 - #{raise_location} + #{__FILE__}:#{__LINE__ - 6} OUTPUT else - expect(output).to eq <<~OUTPUT + expect do + ImLost.trace_exceptions do + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + end.to write <<~OUTPUT x ArgumentError: not the answer - 21 - #{raise_location} + #{__FILE__}:#{__LINE__ - 6} ! ArgumentError: not the answer - 21 - #{rescue_location} + #{__FILE__}:#{__LINE__ - 7} OUTPUT end end it 'allows to disable location information' do - ImLost.trace_exceptions(with_locations: false) do - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - - if RUBY_VERSION.to_f < 3.3 - expect(output).to eq "x ArgumentError: not the answer - 21\n" - else - expect(output).to eq <<~OUTPUT - x ArgumentError: not the answer - 21 - ! ArgumentError: not the answer - 21 - OUTPUT - end - end - - it 'allows to be stacked' do - raise_location = "#{__FILE__}:#{__LINE__ + 5}" - rescue_location = "#{__FILE__}:#{__LINE__ + 5}" + expected = + if RUBY_VERSION.to_f < 3.3 + "x ArgumentError: not the answer - 21\n" + else + <<~OUTPUT + x ArgumentError: not the answer - 21 + ! ArgumentError: not the answer - 21 + OUTPUT + end - ImLost.trace_exceptions(with_locations: false) do - ImLost.trace_exceptions(with_locations: true) do - raise(ArgumentError, 'not the answer - 42') + expect do + ImLost.trace_exceptions(with_locations: false) do + raise(ArgumentError, 'not the answer - 21') rescue ArgumentError # nop end - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - begin - raise(NotImplementedError) - rescue NotImplementedError - # nop - end + end.to write expected + end + it 'allows to be stacked' do if RUBY_VERSION.to_f < 3.3 - expect(output).to eq <<~OUTPUT + expect do + ImLost.trace_exceptions(with_locations: false) do + ImLost.trace_exceptions(with_locations: true) do + raise(ArgumentError, 'not the answer - 42') + rescue ArgumentError + # nop + end + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + end.to write <<~OUTPUT x ArgumentError: not the answer - 42 - #{raise_location} + #{__FILE__}:#{__LINE__ - 10} x ArgumentError: not the answer - 21 OUTPUT else - expect(output).to eq <<~OUTPUT + expect do + ImLost.trace_exceptions(with_locations: false) do + ImLost.trace_exceptions(with_locations: true) do + raise(ArgumentError, 'not the answer - 42') + rescue ArgumentError + # nop + end + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + end.to write <<~OUTPUT x ArgumentError: not the answer - 42 - #{raise_location} + #{__FILE__}:#{__LINE__ - 10} ! ArgumentError: not the answer - 42 - #{rescue_location} + #{__FILE__}:#{__LINE__ - 11} + x ArgumentError: not the answer - 21 + ! ArgumentError: not the answer - 21 + OUTPUT + end + end + + if RUBY_VERSION.to_f >= 3.3 + it 'prints exception tree for rescued exceptions' do + expect do + ImLost.trace_exceptions(with_locations: false) do + begin + begin + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + raise NoMethodError + end + rescue NoMethodError + raise NotImplementedError + end + rescue NotImplementedError + nil + end + end.to write <<~OUTPUT x ArgumentError: not the answer - 21 ! ArgumentError: not the answer - 21 + x NoMethodError: NoMethodError + ! NoMethodError: NoMethodError + [ArgumentError: not the answer - 21] + x NotImplementedError: NotImplementedError + ! NotImplementedError: NotImplementedError + [NoMethodError: NoMethodError] + [ArgumentError: not the answer - 21] OUTPUT end end @@ -314,75 +343,155 @@ def bar = :bar context 'trace locations' do it 'writes call location' do - ImLost.here - - expect(output).to eq ": #{__FILE__}:#{__LINE__ - 2}\n" + expect { ImLost.here }.to write "* #{__FILE__}:#{__LINE__}\n" end it 'writes only when given condition is truethy' do - ImLost.here(1 < 2) - ImLost.here(1 > 2) - - expect(output).to eq ": #{__FILE__}:#{__LINE__ - 3}\n" + expect do + ImLost.here(1 > 2) + ImLost.here(1 < 2) + end.to write "* #{__FILE__}:#{__LINE__ - 1}\n" end it 'returns given argument' do - expect(ImLost.here(:foo)).to be :foo - expect(output).to eq ": #{__FILE__}:#{__LINE__ - 1}\n" - end - - it 'writes only when given block result is truethy' do - ImLost.here { 1 < 2 } - ImLost.here { 1 > 2 } - - expect(output).to eq ": #{__FILE__}:#{__LINE__ - 3}\n" - end + ImLost.output = StringIO.new # prevent output - it 'returns block result' do - expect(ImLost.here { :foo }).to be :foo - expect(output).to eq ": #{__FILE__}:#{__LINE__ - 1}\n" + obj = Object.new + expect(ImLost.here(obj)).to be obj end end context 'dump vars' do it 'prints instance variables' do - sample.add(22, 20) - ImLost.vars(sample) - - expect(output).to eq <<~OUTPUT - = #{__FILE__}:#{__LINE__ - 3} - instance variables: - @result: 42 - @state: :created + expect { ImLost.vars(sample) }.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 1} + > instance variables + @bar: 22 + @foo: 20 OUTPUT end it 'returns given object' do + ImLost.output = StringIO.new # prevent output + expect(ImLost.vars(sample)).to be sample end + context 'when instance variables could not be determined' do + let(:sample) { BasicObject.new } + + it 'it prints an error message' do + expect { ImLost.vars(sample) }.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 1} + !!! unable to retrieve vars + OUTPUT + end + end + context 'when a Binding is given' do it 'prints local variables' do - test = :test - sample = test.to_s - test = sample - ImLost.vars(binding) - - expect(output).to eq <<~OUTPUT - = #{__FILE__}:#{__LINE__ - 3} - local variables: - sample: "test" - test: "test" + expect do + test = :foo_bar_baz + sample = test + sample = sample.to_s + + ImLost.vars(binding) + end.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 2} + > local variables + sample: "foo_bar_baz" + test: :foo_bar_baz OUTPUT end - it 'returns ImLost' do - expect(ImLost.vars(binding)).to be ImLost + it 'returns given bindig' do + ImLost.output = StringIO.new # prevent output + + expect(ImLost.vars(binding)).to be_a Binding + end + end + + context 'when a Thread is given' do + let(:thread) do + Thread.new do + Thread.current[:var] = 21 + Thread.current.thread_variable_set(:result, 42) + end + end + + after { thread.join } + + it 'prints thread variables' do + expect do + thread[:var] = 41 + ImLost.vars(thread.join) + end.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 2} + terminated Thread#{ + " #{thread.__id__}" unless defined?(thread.native_thread_id) + } + > fiber-local variables + var: 21 + > thread variables + result: 42 + OUTPUT + end + + it 'returns given thread' do + ImLost.output = StringIO.new # prevent output + + expect(ImLost.vars(thread)).to be thread + end + end + + if defined?(Fiber.current) && defined?(Fiber.current.storage) + context 'when the current Fiber is given' do + before do + Fiber[:var1] = 22 + Fiber[:var2] = 20 + Fiber[:var3] = Fiber[:var1] + Fiber[:var2] + end + + it 'prints the fiber storage' do + expect { ImLost.vars(Fiber.current) }.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 1} + > fiber storage + var1: 22 + var2: 20 + var3: 42 + OUTPUT + end + + it 'returns given fiber' do + ImLost.output = StringIO.new # prevent output + + expect(ImLost.vars(Fiber.current)).to be Fiber.current + end end + + context 'when a different Fiber is given' do + let(:fiber) { Fiber.new { 42 } } + + after { fiber.kill if defined?(fiber.kill) } # Ruby > v3.3.0 + + it 'it prints an error message' do + expect { ImLost.vars(fiber) }.to write <<~OUTPUT + * #{__FILE__}:#{__LINE__ - 1} + !!! given Fiber is not the current Fiber + #{fiber.inspect} + OUTPUT + end + end + else + pending 'for Fiber is not supported on this platform' end end context '.timer' do + let(:output) { ImLost.output.string } + let(:reset_output!) { ImLost.output = StringIO.new } + + before { ImLost.output = StringIO.new } after { ImLost.timer.delete(ImLost.timer.ids) } it 'supports attributes #count, #empty?, #ids' do @@ -411,7 +520,7 @@ def bar = :bar it 'prints runtime information for an anonymous timer' do id = ImLost.timer.create - ImLost.output = StringIO.new # reset output + reset_output! ImLost.timer[id] location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") @@ -420,7 +529,7 @@ def bar = :bar it 'prints runtime information for a named timer' do ImLost.timer.create(:tt2) - ImLost.output = StringIO.new # reset output + reset_output! ImLost.timer[:tt2] location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") @@ -431,7 +540,7 @@ def bar = :bar it 'prints the runtime of all timers' do ImLost.timer.create(:first) second = ImLost.timer.create - ImLost.output = StringIO.new # reset output + reset_output! ImLost.timer.all location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") diff --git a/spec/support/matcher.rb b/spec/support/matcher.rb new file mode 100644 index 0000000..190d48f --- /dev/null +++ b/spec/support/matcher.rb @@ -0,0 +1,32 @@ +# frozen_string_literal: true + +require 'stringio' + +RSpec::Matchers.define :write do |expected| + match do |actual| + next false unless actual.is_a? Proc + oa = ImLost.output + ImLost.output = StringIO.new + actual.call + expect(@actual = ImLost.output.string).to eq expected + ensure + ImLost.output = oa if oa + end + + failure_message { <<~MESSAGE } + expected: #{expected.inspect} + got: #{@actual.inspect} + + diff: #{differ.diff_as_string(@actual, expected)} + MESSAGE + + def differ + prep = ->(o) { RSpec::Matchers::Composable.surface_descriptions_in(o) } + RSpec::Support::Differ.new( + object_preparer: prep, + color: RSpec::Matchers.configuration.color? + ) + end + + supports_block_expectations +end