feat: Enhanced hook logging

Set APPMAP_LOG_HOOK=true to enabling logging of code hooking events and detailed timestamps.
Set APPMAP_LOG_HOOK_FILE=<file-path>|stderr> to choose the destination of the hook log messages.
When APPMAP_PROFILE_HOOK=true (an existing option) be sure and dump the profile info on exit.
Disable hooking of ActiveRecord

Fixes https://github.com/getappmap/appmap-ruby/issues/302

Steps to use this branch

Update Gemfile:

git_source(:github) { |repo| "https://github.com/#{repo}.git" }

gem 'appmap',
  github: 'applandinc/appmap-ruby',
  branch: 'feat/enhanced-hook-logging',
  group: %i[test development]

Update bundle:

bundle update appmap

Run application with env vars set (example: rails test; you can also run bundle exec rspec as appropriate to your project):

DISABLE_SPRING=true APPMAP_LOG_HOOK=true APPMAP_PROFILE_HOOK=true rails test

With these options, you'll see some hook profile information printed to the console.

A file appmap_hook.log will also be created. This file does not have trace information about your code, it's only diagnostic information about the time take to instrument the code as it loads.

Note DISABLE_SPRING=true ensures that the command does not run in an existing spring runner with the wrong environment.

Usage example

Here's how I run appmap on our own AppMap Server code:

$ APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true be rspec spec/requests/authn_provider_*

Randomized with seed 52613

AuthnProviderVscodeController
  .vscode
    when logged in
      accepts a redirect_url parameter
      re-uses an existing API key
      redirects with the API key
      does not allow non-vscode extension redirect_url parameters
    when anonymous
      it is not found

AuthnProviderController
  .vscode
    when logged in
      accepts a source parameter
      stores the azure user id
      requires a redirect_url parameter
      redirects with the API key
      creates a new API key based on the source
      re-uses an existing API key
      accepts a redirect_url parameter
      non-vscode protocol or localhost redirect_url parameters
        does not remember the azure user id
        are not allowed
    when anonymous
      saves the azure user id and redirects to the login page
      redirects to the login page

AuthnProviderVscodeController
  .vscode
    when logged in
      accepts a redirect_url parameter
      requires a redirect_url
      does not allow non-localhost redirect_url parameters
      re-uses an existing API key
    when anonymous
      it is not found

Finished in 1.99 seconds (files took 3.02 seconds to load)
21 examples, 0 failures

Randomized with seed 52613

AppMap: Package actionpack-6.1.4.1 took 0.039431999999999995 seconds to hook
AppMap: Package octokit-4.21.0 took 0.0829740000000002 seconds to hook
AppMap: Package signet-0.16.0 took 0.005195 seconds to hook
AppMap: Package sendgrid-ruby-6.5.1 took 0.020284000000000003 seconds to hook
AppMap: Package railties-6.1.4.1 took 0.008904 seconds to hook
AppMap: Package activejob-6.1.4.1 took 0.011273 seconds to hook
AppMap: Package actionview-6.1.4.1 took 0.027660999999999995 seconds to hook
AppMap: Package app/helpers took 0.002634 seconds to hook
AppMap: Package app/controllers took 0.010565 seconds to hook
AppMap: Package app/services took 0.002325999999999999 seconds to hook
AppMap: Package app/models took 0.015457000000000002 seconds to hook
Coverage report generated for RSpec to /Users/kgilpin/source/appland/appland/coverage. 486 / 686 LOC (70.85%) covered.

The file appmap_hook.log contains many lines like these (first column is timestamp with nanosecond resolution):

1670873468.4681358      builtin begin   Initiating hook for builtin ActiveSupport::Callbacks::CallbackSequence invoke_before
1670873468.46827        Hooking ActiveSupport::Callbacks::CallbackSequence#invoke_before at line /Users/kgilpin/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:511
1670873468.46831        builtin end     Completed hook for builtin ActiveSupport::Callbacks::CallbackSequence invoke_before
1670873468.46832        builtin begin   Initiating hook for builtin ActiveSupport::Callbacks::CallbackSequence invoke_after
1670873468.4683578      Hooking ActiveSupport::Callbacks::CallbackSequence#invoke_after at line /Users/kgilpin/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:515
1670873468.4683719      builtin end     Completed hook for builtin ActiveSupport::Callbacks::CallbackSequence invoke_after
1670873468.4687412      builtin begin   Initiating hook for builtin ActiveSupport::SecurityUtils secure_compare
1670873468.468792       Hooking ActiveSupport::SecurityUtils#secure_compare at line /Users/kgilpin/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/security_utils.rb:33
1670873468.4689689      builtin end     Completed hook for builtin ActiveSupport::SecurityUtils secure_compare
1670873468.46898        builtin begin   Initiating hook for builtin ActiveSupport run_load_hooks
1670873468.46902        Hooking ActiveSupport::LazyLoadHooks#run_load_hooks at line /Users/kgilpin/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/lazy_load_hooks.rb:49

and the a very simple summary at the end:

Elapsed time:
builtin:        0.010101556777954102
usercode:       0.3632802963256836

getappmap / appmap-ruby

feat: Enhanced hook logging #303

Steps to use this branch

Usage example