search

getappmap / appmap-ruby

AppMap client agent for Ruby
https://appland.org
Other
100 stars 13 forks source link

Undefined method 'size' for Module. #341

Closed tommyalvarez closed 1 year ago

tommyalvarez commented 1 year ago

I'm using the AppMap ruby agent to build sequence diagrams. I'm using the record feature of the gem.

It would seem that some hooks added by the agent are causing issues and my app to crash. Some info of the app:

Ruby version: 3.0.5 Rails: 6.1.7.1 appmap (0.102.0)

Stacktrace:

undefined method `size' for FacebookConversionsApi2023-07-24 20:25:01.155 [WARN ]     undefined method `size' for FacebookConversionsApi (pid:99841)
2023-07-24 20:25:01.186 [ERROR]     Bugsnag notified: [#<NoMethodError: undefined method `size' for FacebookConversionsApi>]
    Metadata: {}
    #0 initialize at gems/delayed_job-4.1.9/lib/delayed/performable_method.rb:6
    #1 new at gems/delayed_job-4.1.9/lib/delayed/message_sending.rb:11
    #2 method_missing at gems/delayed_job-4.1.9/lib/delayed/message_sending.rb:11
    #3 detect_size at gems/appmap-0.102.0/lib/appmap/value_inspector.rb:11
    #4 add_size at gems/appmap-0.102.0/lib/appmap/event.rb:67
    #5 block (2 levels) in build_from_invocation at gems/appmap-0.102.0/lib/appmap/event.rb:282
    #6 block in build_from_invocation at gems/appmap-0.102.0/lib/appmap/event.rb:281
    #7 build_from_invocation at gems/appmap-0.102.0/lib/appmap/event.rb:275
    #8 handle_return at gems/appmap-0.102.0/lib/appmap/handler/function_handler.rb:15
    #9 after_hook at gems/appmap-0.102.0/lib/appmap/hook/method.rb:116
    #10 block in trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:55
    #11 with_disabled_hook at gems/appmap-0.102.0/lib/appmap/hook/method.rb:125
    #12 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:55
    #13 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #14 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #15 facebook_conversions_api_add_to_cart at app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:10
    #16 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #17 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #18 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #19 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #20 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #21 handle_line_item_addition at app/controllers/concerns/checkout_helpers.rb:62
    #22 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #23 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #24 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #25 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #26 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #27 order_line_items_updated_callbacks at app/controllers/concerns/checkout_helpers.rb:53
    #28 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #29 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #30 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #31 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #32 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #33 handle_create_or_update at app/controllers/api/line_items_controller.rb:94
    #34 create at app/controllers/api/line_items_controller.rb:32
    #35 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #36 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #37 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #38 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #39 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #40 send_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/basic_implicit_render.rb:6
    #41 process_action at gems/actionpack-6.1.7.2/lib/abstract_controller/base.rb:228
    #42 process_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/rendering.rb:30
    #43 block in process_action at gems/actionpack-6.1.7.2/lib/abstract_controller/callbacks.rb:42
    #44 block in run_callbacks at gems/activesupport-6.1.7.2/lib/active_support/callbacks.rb:117
    #45 with_renderer at gems/actiontext-6.1.7.2/lib/action_text/rendering.rb:20
    #46 block (4 levels) in <class:Engine> at gems/actiontext-6.1.7.2/lib/action_text/engine.rb:59
    #47 instance_exec at gems/activesupport-6.1.7.2/lib/active_support/callbacks.rb:126
    #48 block in run_callbacks at gems/activesupport-6.1.7.2/lib/active_support/callbacks.rb:126
    #49 run_callbacks at gems/activesupport-6.1.7.2/lib/active_support/callbacks.rb:137
    #50 process_action at gems/actionpack-6.1.7.2/lib/abstract_controller/callbacks.rb:41
    #51 process_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/rescue.rb:22
    #52 block in process_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/instrumentation.rb:34
    #53 block in instrument at gems/activesupport-6.1.7.2/lib/active_support/notifications.rb:203
    #54 instrument at gems/activesupport-6.1.7.2/lib/active_support/notifications/instrumenter.rb:24
    #55 instrument at gems/activesupport-6.1.7.2/lib/active_support/notifications.rb:203
    #56 process_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/instrumentation.rb:33
    #57 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #58 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #59 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #60 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #61 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #62 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #63 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #64 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:45
    #65 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #66 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #67 process_action at gems/actionpack-6.1.7.2/lib/action_controller/metal/params_wrapper.rb:249
    #68 process_action at gems/searchkick-4.6.3/lib/searchkick/logging.rb:212
    #69 process_action at gems/activerecord-6.1.7.2/lib/active_record/railties/controller_runtime.rb:27
    #70 process at gems/actionpack-6.1.7.2/lib/abstract_controller/base.rb:165
    #71 process at gems/actionview-6.1.7.2/lib/action_view/rendering.rb:39
    #72 dispatch at gems/actionpack-6.1.7.2/lib/action_controller/metal.rb:190
    #73 dispatch at gems/actionpack-6.1.7.2/lib/action_controller/metal.rb:254
    #74 dispatch at gems/actionpack-6.1.7.2/lib/action_dispatch/routing/route_set.rb:50
    #75 serve at gems/actionpack-6.1.7.2/lib/action_dispatch/routing/route_set.rb:33
    #76 block in serve at gems/actionpack-6.1.7.2/lib/action_dispatch/journey/router.rb:50
    #77 each at gems/actionpack-6.1.7.2/lib/action_dispatch/journey/router.rb:32
    #78 serve at gems/actionpack-6.1.7.2/lib/action_dispatch/journey/router.rb:32
    #79 call at gems/actionpack-6.1.7.2/lib/action_dispatch/routing/route_set.rb:842
    #80 call! at gems/omniauth-2.1.1/lib/omniauth/strategy.rb:202
    #81 call at gems/omniauth-2.1.1/lib/omniauth/strategy.rb:169
    #82 call! at gems/omniauth-2.1.1/lib/omniauth/strategy.rb:202
    #83 call at gems/omniauth-2.1.1/lib/omniauth/strategy.rb:169
    #84 call at gems/omniauth-2.1.1/lib/omniauth/builder.rb:44
    #85 call at gems/dragonfly-1.4.0/lib/dragonfly/middleware.rb:14
    #86 call at gems/scout_apm-5.3.3/lib/scout_apm/instant/middleware.rb:55
    #87 call at gems/scout_apm-5.3.3/lib/scout_apm/middleware.rb:20
    #88 call at gems/rack-attack-6.5.0/lib/rack/attack.rb:99
    #89 call! at gems/rack-robustness-1.1.0/lib/rack/robustness.rb:104
    #90 call at gems/rack-robustness-1.1.0/lib/rack/robustness.rb:95
    #91 call at gems/rack-attack-6.5.0/lib/rack/attack.rb:113
    #92 block in call at gems/warden-1.2.9/lib/warden/manager.rb:36
    #93 catch at gems/warden-1.2.9/lib/warden/manager.rb:34
    #94 call at gems/warden-1.2.9/lib/warden/manager.rb:34
    #95 call at gems/rack-2.2.6.4/lib/rack/tempfile_reaper.rb:15
    #96 call at gems/rack-2.2.6.4/lib/rack/etag.rb:27
    #97 call at gems/rack-2.2.6.4/lib/rack/conditional_get.rb:40
    #98 call at gems/rack-2.2.6.4/lib/rack/head.rb:12
    #99 call at gems/actionpack-6.1.7.2/lib/action_dispatch/http/permissions_policy.rb:22
    #100 call at gems/actionpack-6.1.7.2/lib/action_dispatch/http/content_security_policy.rb:19
    #101 context at gems/rack-2.2.6.4/lib/rack/session/abstract/id.rb:266
    #102 call at gems/rack-2.2.6.4/lib/rack/session/abstract/id.rb:260
    #103 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/cookies.rb:697
    #104 call at gems/activerecord-6.1.7.2/lib/active_record/migration.rb:601
    #105 block in call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/callbacks.rb:27
    #106 run_callbacks at gems/activesupport-6.1.7.2/lib/active_support/callbacks.rb:98
    #107 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/callbacks.rb:26
    #108 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/executor.rb:14
    #109 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #110 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #111 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:45
    #112 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #113 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #114 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/actionable_exceptions.rb:18
    #115 call at gems/bugsnag-6.20.0/lib/bugsnag/integrations/rack.rb:51
    #116 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/debug_exceptions.rb:29
    #117 call_app at gems/web-console-4.2.0/lib/web_console/middleware.rb:132
    #118 block in call at gems/web-console-4.2.0/lib/web_console/middleware.rb:28
    #119 catch at gems/web-console-4.2.0/lib/web_console/middleware.rb:17
    #120 call at gems/web-console-4.2.0/lib/web_console/middleware.rb:17
    #121 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/show_exceptions.rb:33
    #122 call_app at gems/railties-6.1.7.2/lib/rails/rack/logger.rb:37
    #123 block in call at gems/railties-6.1.7.2/lib/rails/rack/logger.rb:26
    #124 block in tagged at gems/activesupport-6.1.7.2/lib/active_support/tagged_logging.rb:99
    #125 tagged at gems/activesupport-6.1.7.2/lib/active_support/tagged_logging.rb:37
    #126 tagged at gems/activesupport-6.1.7.2/lib/active_support/tagged_logging.rb:99
    #127 call at gems/railties-6.1.7.2/lib/rails/rack/logger.rb:26
    #128 call at gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13
    #129 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/remote_ip.rb:81
    #130 block in call at gems/rack-timeout-0.6.0/lib/rack/timeout/core.rb:151
    #131 timeout at gems/rack-timeout-0.6.0/lib/rack/timeout/support/timeout.rb:19
    #132 call at gems/rack-timeout-0.6.0/lib/rack/timeout/core.rb:150
    #133 call at gems/request_store-1.5.0/lib/request_store/middleware.rb:19
    #134 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/request_id.rb:26
    #135 call at gems/rack-2.2.6.4/lib/rack/method_override.rb:24
    #136 call at gems/rack-2.2.6.4/lib/rack/runtime.rb:22
    #137 call at gems/rack-rewrite-1.5.1/lib/rack/rewrite.rb:24
    #138 call at gems/activesupport-6.1.7.2/lib/active_support/cache/strategy/local_cache_middleware.rb:29
    #139 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/executor.rb:14
    #140 bind_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #141 do_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:40
    #142 trace_call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:49
    #143 call at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:16
    #144 block in hook_method_def at gems/appmap-0.102.0/lib/appmap/hook/method/ruby3.rb:63
    #145 call at gems/appmap-0.102.0/lib/appmap/middleware/remote_recording.rb:131
    #146 forward at gems/rack-cache-1.12.1/lib/rack/cache/context.rb:141
    #147 pass at gems/rack-cache-1.12.1/lib/rack/cache/context.rb:148
    #148 invalidate at gems/rack-cache-1.12.1/lib/rack/cache/context.rb:160
    #149 call! at gems/rack-cache-1.12.1/lib/rack/cache/context.rb:75
    #150 call at gems/rack-cache-1.12.1/lib/rack/cache/context.rb:52
    #151 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/static.rb:24
    #152 call at gems/dragonfly-1.4.0/lib/dragonfly/cookie_monster.rb:9
    #153 call at gems/rack-2.2.6.4/lib/rack/sendfile.rb:110
    #154 call at gems/actionpack-6.1.7.2/lib/action_dispatch/middleware/host_authorization.rb:148
    #155 call at gems/utf8-cleaner-1.0.0/lib/utf8-cleaner/middleware.rb:21
    #156 call at gems/railties-6.1.7.2/lib/rails/engine.rb:539
    #157 public_send at gems/railties-6.1.7.2/lib/rails/railtie.rb:207
    #158 method_missing at gems/railties-6.1.7.2/lib/rails/railtie.rb:207
    #159 call at gems/rack-2.2.6.4/lib/rack/deflater.rb:44
    #160 call at gems/rack-2.2.6.4/lib/rack/chunked.rb:98
    #161 call at gems/puma-5.6.4/lib/puma/configuration.rb:252
    #162 block in handle_request at gems/puma-5.6.4/lib/puma/request.rb:77
    #163 with_force_shutdown at gems/puma-5.6.4/lib/puma/thread_pool.rb:340
    #164 handle_request at gems/puma-5.6.4/lib/puma/request.rb:76
    #165 process_client at gems/puma-5.6.4/lib/puma/server.rb:441
    #166 block in spawn_thread at gems/puma-5.6.4/lib/puma/thread_pool.rb:147 (pid:99841)
2023-07-24 20:25:01.210 [FATAL]     NoMethodError (undefined method `size' for FacebookConversionsApi):

.../app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:10:in `facebook_conversions_api_add_to_cart'
.../app/controllers/concerns/checkout_helpers.rb:62:in `handle_line_item_addition'
.../app/controllers/concerns/checkout_helpers.rb:53:in `order_line_items_updated_callbacks'
.../app/controllers/api/line_items_controller.rb:94:in `handle_create_or_update'
.../app/controllers/api/line_items_controller.rb:32:in `create' (pid:99841)

The key part seems to be here:

    #0 initialize at gems/delayed_job-4.1.9/lib/delayed/performable_method.rb:6
    #1 new at gems/delayed_job-4.1.9/lib/delayed/message_sending.rb:11
    #2 method_missing at gems/delayed_job-4.1.9/lib/delayed/message_sending.rb:11
    #3 detect_size at gems/appmap-0.102.0/lib/appmap/value_inspector.rb:11

Where app map tries to inspect a value. The value inspected remains unknown to me, as it's a little bit tricky to debug the code at that point, but it starts from a Delayed job method call to #delay with a hash argument.

Unfortunately, this is impeding me to fully use appmap as it crashes my application on a very important flow.

kgilpin commented 1 year ago

Thanks for reporting this issue. Can you run with the environment variable APPMAP_LOG_HOOK as described here - https://appmap.io/docs/reference/appmap-ruby.html#advanced-runtime-options

and share the resulting log file? If you don’t want to attach it here, you can send us a DM through the AppMap Slack. This way we can see which method is causing the error, and we will be able to tell you how to disable it and get your app running again while we fix the problem.

tommyalvarez commented 1 year ago

Hi @kgilpin.

Attaching the logs appmap_hook.log

kgilpin commented 1 year ago

Thanks, here's what I see so far. AppMap is recording a method call to this function:

    #15 facebook_conversions_api_add_to_cart at app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:10

As it records that function, it's writing out the data for the self and arguments. That logic includes this snippet:

    def detect_size(value)
      # Don't risk calling #size on things like data-access objects, which can and will issue queries for this information.
      if value.is_a?(Array) || value.is_a?(Hash)
        value.size
      end
    end

value in this case appears to be a Delayed::DelayedProxy (from delayed_job, because that's what is next up the call stack).

The DelayedProxy has indicated that it is an Array or Hash - I don't see how this is possible, but it seems to be happening.

AppMap then tries to call the size method on the DelayedProxy. The DelayedProxy creates a PerformableObject, which raises #<NoMethodError: undefined methodsize' for FacebookConversionsApi>`

FacebookConversionsApi may be self or it may be a parameter of the method indicated earlier, app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:10.

Somehow, FacebookConversionsApi is return true from value.is_a?(Array) || value.is_a?(Hash), but it does not implement size. I don't honestly know how this is possible - it may be evident from looking at the code.

You can disable recording of facebook_conversions_api_add_to_cart using appmap.yml.

Add the fully qualified class name and method name to the exclude section (as described here:

name: my_project
language: ruby
appmap_dir: tmp/appmap
packages:
- path: app
exclude:
- FacebookConversionsApi::TrackingHelpers#facebook_conversions_api_add_to_cart

To fix this in appmap-ruby, I'll add a guard clause to verify that :size is really defined on value.

kgilpin commented 1 year ago

:tada: This issue has been resolved in version 0.102.1 :tada:

The release is available on:

Your semantic-release bot :package::rocket:

tommyalvarez commented 1 year ago

@kgilpin unfortunately, even with the fix the issue is still happening in the same place. Even the workaround won't have any effect.

I believe that the issue might be that value is like a method or proc that gets called when referenced, so it returns "something", and for the purpose of the if that evaluates if it's a hash, array or even respond_to :size, it returns a non-nil value so it evaluates as a truthy.

The funny thing is that each time value gets referenced at this point, even with a method, it enqueues a new job for me. For instance I was able to debug the point where the bug happens and see for yourself:

[12, 21] in /Users/tommy/.rvm/gems/ruby-3.0.5/gems/appmap-0.102.1/lib/appmap/value_inspector.rb
   12:           value.size
   13:         end
   14:       rescue NoMethodError => e
   15:         byebug
   16:       end
=> 17:     end
   18:
   19:     def detect_schema(

test = value.is_a?(Array)

2023-07-25 17:50:14.812 [DEBUG]     TRANSACTION (12.3ms)  BEGIN (pid:22960)
2023-07-25 17:50:14.816 [DEBUG]     ↳ .../app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:9:in `facebook_conversions_api_add_to_cart' (pid:22960)
2023-07-25 17:50:14.818 [DEBUG]     Delayed::Backend::ActiveRecord::Job Create (0.9ms)  INSERT INTO "delayed_jobs" ("handler", "run_at", "queue", "created_at", "updated_at") VALUES ('--- !ruby/object:Delayed::PerformableMethod
object: !ruby/module ''FacebookConversionsApi''
method_name: :is_a?
args:
- !ruby/class ''Array''
', '2023-07-25 20:50:14.798890', 'default', '2023-07-25 20:50:14.798954', '2023-07-25 20:50:14.798954') RETURNING "id" (pid:22960)
2023-07-25 17:50:14.818 [DEBUG]     ↳ .../app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:9:in `facebook_conversions_api_add_to_cart' (pid:22960)
2023-07-25 17:50:14.819 [DEBUG]     Query Trace:
      app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:9:in `facebook_conversions_api_add_to_cart'
      app/controllers/concerns/checkout_helpers.rb:62:in `handle_line_item_addition'
      app/controllers/concerns/checkout_helpers.rb:53:in `order_line_items_updated_callbacks'
      app/controllers/api/line_items_controller.rb:94:in `handle_create_or_update'
      app/controllers/api/line_items_controller.rb:32:in `create' (pid:22960)
2023-07-25 17:50:14.819 [DEBUG]     ↳ .../app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:9:in `facebook_conversions_api_add_to_cart' (pid:22960)
2023-07-25 17:50:14.820 [DEBUG]     TRANSACTION (0.5ms)  COMMIT (pid:22960)
2023-07-25 17:50:14.820 [DEBUG]     ↳ .../app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:9:in `facebook_conversions_api_add_to_cart' (pid:22960)
#<Delayed::Backend::ActiveRecord::Job id: 2566514, priority: 0, attempts: 0, handler: "--- !ruby/object:Delayed::PerformableMethod\nobject...", last_error: nil, run_at: "2023-07-25 16:50:14.798890000 -0400", locked_at: nil, failed_at: nil, locked_by: nil, queue: "default", created_at: "2023-07-25 16:50:14.798954000 -0400", updated_at: "2023-07-25 16:50:14.798954000 -0400">

(byebug) test
#<Delayed::Backend::ActiveRecord::Job id: 2566514, priority: 0, attempts: 0, handler: "--- !ruby/object:Delayed::PerformableMethod\nobject...", last_error: nil, run_at: "2023-07-25 16:50:14.798890000 -0400", locked_at: nil, failed_at: nil, locked_by: nil, queue: "default", created_at: "2023-07-25 16:50:14.798954000 -0400", updated_at: "2023-07-25 16:50:14.798954000 -0400">

I think the issue should be reopened.

kgilpin commented 1 year ago

What's interesting / weird is that appmap-ruby isn't calling a method on the object, it's using is_a?

https://github.com/getappmap/appmap-ruby/blob/master/lib/appmap/value_inspector.rb#L10

An object that overrides is_a? to always return true is definitely asking for trouble. And I guess if it's overriding respond_to? to also always return true, then it's even more so.

Because the object is wrapped with a proxy, calling any method on it causes it to be enqueued:

https://github.com/collectiveidea/delayed_job/blob/master/lib/delayed/message_sending.rb#L11

That's why you are seeing that behavior.

So the solution will definitely be to find out which method is triggering this behavior and add it to the exclude: list in the config file. It looks to me like the thing to exclude is #15 facebook_conversions_api_add_to_cart at app/controllers/concerns/facebook_conversions_api/tracking_helpers.rb:10. The hook log file should show this method being skipped over during instrumentation. If it's not, maybe Spring needs to be disabled or restarted?