feat: Enhance the hook log a lot

Author: kgilpin

lib/appmap/config.rb

@@ -8,6 +8,7 @@
 require 'appmap/service/guesser'
 require 'appmap/swagger/configuration'
 require 'appmap/depends/configuration'
+require_relative './hook_log'
 
 module AppMap
   class Config
@@ -499,7 +500,11 @@ def lookup_package(cls, method)
 
     def never_hook?(cls, method)
       _, separator, = ::AppMap::Hook.qualify_method_name(method)
-      return true if exclude.member?(cls.name) || exclude.member?([ cls.name, separator, method.name ].join)
+      if exclude.member?(cls.name) || exclude.member?([ cls.name, separator, method.name ].join)
+        HookLog.log "Hooking of #{method} disabled by configuration" if HookLog.enabled?
+        return true
+      end
+      false
     end
   end
 end

lib/appmap/hook.rb

@@ -19,7 +19,7 @@ def hook_builtins?
         Mutex.new.synchronize do
           @hook_builtins = true if @hook_builtins.nil?
 
-          return false unless @hook_builtins
+          next false unless @hook_builtins
 
           @hook_builtins = false
           true
@@ -101,48 +101,52 @@ def hook_builtins
       hook_loaded_code = lambda do |hooks_by_class, builtin|
         hooks_by_class.each do |class_name, hooks|
           Array(hooks).each do |hook|
-            if builtin && hook.package.require_name && hook.package.require_name != 'ruby'
-              require hook.package.require_name
-            end
-
-            Array(hook.method_names).each do |method_name|
-              method_name = method_name.to_sym
-
+            HookLog.builtin class_name do
+              if builtin && hook.package.require_name && hook.package.require_name != 'ruby'
+                begin
+                  require hook.package.require_name
+                rescue
+                  HookLog.load_error hook.package.require_name, "Unable to require #{hook.package.require_name}: #{$!}" if HookLog.enabled?
+                  next
+                end
+              end
+  
               begin
                 base_cls = Object.const_get class_name
               rescue NameError
+                HookLog.load_error class_name, "Class #{class_name} not found in global scope" if HookLog.enabled?
                 next
               end
-
-              HookLog.builtin_begin class_name, method_name if HookLog.enabled?
-
-              hook_method = lambda do |entry|
-                cls, method = entry
-                next if config.never_hook?(cls, method)
-
-                hook.package.handler_class.new(hook.package, cls, method).activate
-              end
-
-              methods = []
-              # irb(main):001:0> Kernel.public_instance_method(:system)
-              # (irb):1:in `public_instance_method': method `system' for module `Kernel' is  private (NameError)
-              if base_cls == Kernel
-                methods << [base_cls, base_cls.instance_method(method_name)] rescue nil
-              end
-              methods << [base_cls, base_cls.public_instance_method(method_name)] rescue nil
-              methods << [base_cls, base_cls.protected_instance_method(method_name)] rescue nil
-              if base_cls.respond_to?(:singleton_class)
-                methods << [base_cls.singleton_class, base_cls.singleton_class.public_instance_method(method_name)] rescue nil
-                methods << [base_cls.singleton_class, base_cls.singleton_class.protected_instance_method(method_name)] rescue nil
-              end
-              methods.compact!
-              if methods.empty?
-                HookLog.log "Method #{method_name} not found on #{base_cls.name}" if HookLog.enabled?
-              else
-                methods.each(&hook_method)
+  
+              Array(hook.method_names).each do |method_name|
+                method_name = method_name.to_sym
+  
+                hook_method = lambda do |entry|
+                  cls, method = entry
+                  next if config.never_hook?(cls, method)
+  
+                  hook.package.handler_class.new(hook.package, cls, method).activate
+                end
+  
+                methods = []
+                # irb(main):001:0> Kernel.public_instance_method(:system)
+                # (irb):1:in `public_instance_method': method `system' for module `Kernel' is  private (NameError)
+                if base_cls == Kernel
+                  methods << [base_cls, base_cls.instance_method(method_name)] rescue nil
+                end
+                methods << [base_cls, base_cls.public_instance_method(method_name)] rescue nil
+                methods << [base_cls, base_cls.protected_instance_method(method_name)] rescue nil
+                if base_cls.respond_to?(:singleton_class)
+                  methods << [base_cls.singleton_class, base_cls.singleton_class.public_instance_method(method_name)] rescue nil
+                  methods << [base_cls.singleton_class, base_cls.singleton_class.protected_instance_method(method_name)] rescue nil
+                end
+                methods.compact!
+                if methods.empty?
+                  HookLog.load_error [ base_cls.name, method_name ].join('[#.]'), "Method #{method_name} not found on #{base_cls.name}" if HookLog.enabled?
+                else
+                  methods.each(&hook_method)
+                end
               end
-
-              HookLog.builtin_end class_name, method_name if HookLog.enabled?
             end
           end
         end
@@ -159,17 +163,14 @@ def trace_location(trace_point)
 
     def trace_end(trace_point)
       location = trace_location(trace_point)
-      begin
-        HookLog.usercode_begin location if HookLog.enabled?
-
-        return unless @trace_locations.add?(location)
-
+      return unless @trace_locations.add?(location)
+      HookLog.on_load location do
         path = trace_point.path
         enabled = !@notrace_paths.member?(path) && config.path_enabled?(path)
         unless enabled
           HookLog.log 'Not hooking - path is not enabled' if HookLog.enabled?
           @notrace_paths << path
-          return
+          next
         end
 
         cls = trace_point.self
@@ -191,7 +192,7 @@ def trace_end(trace_point)
             method = begin
                 hook_cls.instance_method(method_id)
               rescue NameError
-                HookLog.log "Method #{hook_cls} #{fn} is not accessible: #{$!}" if HookLog.enabled?
+                HookLog.load_error [ hook_cls, method_id ].join('[#.]'), "Method #{hook_cls} #{method_id} is not accessible: #{$!}" if HookLog.enabled?
                 next
               end
 
@@ -239,8 +240,6 @@ def trace_end(trace_point)
             @module_load_times[location] += elapsed
           end
         end
-      ensure
-        HookLog.usercode_end(location) if HookLog.enabled?
       end
     end
   end

lib/appmap/hook_log.rb

@@ -19,39 +19,62 @@ def initialize
     end
 
     def start_time(timer)
-      @elapsed[timer] << [Time.now.to_f]
+      @elapsed[timer] << [Util.gettime]
     end
 
     def end_time(timer)
-      @elapsed[timer][-1] = Time.now.to_f - @elapsed[timer].last[0]
+      unless @elapsed[timer].last.is_a?(Array)
+        warn "AppMap: Unbalanced timing data in hook log"
+        @elapsed[timer].pop
+        return
+      end
+
+      @elapsed[timer][-1] = Util.gettime - @elapsed[timer].last[0]
     end
 
     class << self
       def enabled?
         LOG || LOG_HOOK
       end
 
-      def builtin_begin(class_name, method_name)
-        log "builtin\tbegin\tInitiating hook for builtin #{class_name} #{method_name}"
-        @hook_log.start_time :builtin
-      end
+      def builtin(class_name, &block)
+        return yield unless enabled?
 
-      def builtin_end(class_name, method_name)
-        @hook_log.end_time :builtin
-        log "builtin\tend\tCompleted hook for builtin #{class_name} #{method_name}"
+        begin
+          log "eager\tbegin\tInitiating eager hook for #{class_name}"
+          @hook_log.start_time :eager
+
+          yield
+        ensure
+          @hook_log.end_time :eager
+          log "eager\tend\tCompleted eager hook for #{class_name}"
+        end
       end
 
-      def usercode_begin(location)
-        log "usercode\tbegin\tClass or module defined at location #{location}"
-        @hook_log.start_time :usercode
+      def on_load(location, &block)
+        return yield unless enabled?
+
+        begin
+          log "on-load\tbegin\tInitiating on-load hook for class or module defined at location #{location}"
+          @hook_log.start_time :on_load
+
+          yield
+        ensure
+          @hook_log.end_time :on_load
+          log "on-load\tend\tCompleted on-load hook for location #{location}"
+        end
       end
 
-      def usercode_end(location)
-        @hook_log.end_time :usercode
-        log "usercode\tend\tCompleted location #{location}"
+      def load_error(name, msg)
+        log "load_error\t#{name}\t#{msg}"
       end
 
       def log(msg)
+        unless HookLog.enabled?
+          warn "AppMap: HookLog is not enabled. Disregarding message #{msg}"
+          return
+        end
+
         @hook_log ||= HookLog.new
         @hook_log.log msg
       end
@@ -69,7 +92,7 @@ def log(msg)
       if LOG_HOOK_FILE == 'stderr'
         msg = "AppMap: #{msg}"
       end
-      msg = "#{Time.new.to_f}\t#{msg}"
+      msg = "#{Util.gettime}\t#{msg}"
       @file_handle.puts(msg)
     end
   end