search

avo-hq / avo

Build Ruby on Rails apps 10x faster
https://avohq.io
Other
1.5k stars 238 forks source link

License check causing error #2788

Closed Reizar closed 2 months ago

Reizar commented 4 months ago

Describe the bug

Avo throws a 500 error whenever any page is accessed. There's an issue with the license check logic from what I can tell.

See the following stack trace:

web    | Started GET "/avo" for 127.0.0.1 at 2024-05-22 10:07:32 +1200
web    |   ActiveRecord::SchemaMigration Pluck (1.2ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
web    | Processing by Avo::HomeController#index as HTML
web    |   AdminUser Load (1.1ms)  SELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id" = $1 ORDER BY "admin_users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
web    | [Avo] 2024-05-22 10:07:32 +1200: Performing request to avohq.io API to check license availability.
web    | Completed 500 Internal Server Error in 1329ms (ActiveRecord: 31.4ms | Allocations: 560636)
web    |
web    |
web    |
web    | TypeError (singleton can't be dumped):
web    |
web    | activesupport (7.0.8) lib/active_support/cache.rb:1013:in `dump'
web    | activesupport (7.0.8) lib/active_support/cache.rb:1013:in `dup_value!'
web    | activesupport (7.0.8) lib/active_support/cache/memory_store.rb:31:in `dump'
web    | activesupport (7.0.8) lib/active_support/cache.rb:637:in `serialize_entry'
web    | activesupport (7.0.8) lib/active_support/cache/memory_store.rb:167:in `write_entry'
web    | activesupport (7.0.8) lib/active_support/cache.rb:507:in `block in write'
web    | activesupport (7.0.8) lib/active_support/cache.rb:783:in `block in instrument'
web    | activesupport (7.0.8) lib/active_support/notifications.rb:208:in `instrument'
web    | activesupport (7.0.8) lib/active_support/cache.rb:783:in `instrument'
web    | activesupport (7.0.8) lib/active_support/cache.rb:505:in `write'
web    | avo (3.7.4) lib/avo/licensing/h_q.rb:127:in `cache_response'
web    | avo (3.7.4) lib/avo/licensing/h_q.rb:114:in `perform_and_cache_request'
web    | avo (3.7.4) lib/avo/licensing/h_q.rb:88:in `make_request'
web    | avo (3.7.4) lib/avo/licensing/h_q.rb:33:in `response'
web    | avo (3.7.4) app/controllers/concerns/avo/initializes_avo.rb:9:in `init_app'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:400:in `block in make_lambda'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:199:in `block (2 levels) in halting'
web    | actionpack (7.0.8) lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:200:in `block in halting'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:595:in `block in invoke_before'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:595:in `each'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:595:in `invoke_before'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:116:in `block in run_callbacks'
web    | i18n (1.14.5) lib/i18n.rb:351:in `with_locale'
web    | avo (3.7.4) app/controllers/avo/application_controller.rb:284:in `set_avo_locale'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | turbo-rails (2.0.5) lib/turbo-rails.rb:24:in `with_request_id'
web    | turbo-rails (2.0.5) app/controllers/concerns/turbo/request_id_tracking.rb:10:in `turbo_tracking_request_id'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | audited (5.4.2) lib/audited/sweeper.rb:16:in `around'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | audited (5.4.2) lib/audited/sweeper.rb:16:in `around'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | graphiti-rails (0.4.0) lib/graphiti/rails/debugging.rb:13:in `block in debug_graphiti'
web    | graphiti (1.3.9) lib/graphiti/debugger.rb:110:in `debug'
web    | graphiti-rails (0.4.0) lib/graphiti/rails/debugging.rb:12:in `debug_graphiti'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | graphiti-rails (0.4.0) lib/graphiti/rails/context.rb:17:in `block in wrap_graphiti_context'
web    | graphiti (1.3.9) lib/graphiti.rb:33:in `with_context'
web    | graphiti-rails (0.4.0) lib/graphiti/rails/context.rb:16:in `wrap_graphiti_context'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:138:in `run_callbacks'
web    | actionpack (7.0.8) lib/abstract_controller/callbacks.rb:233:in `process_action'
web    | actionpack (7.0.8) lib/action_controller/metal/rescue.rb:23:in `process_action'
web    | actionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
web    | activesupport (7.0.8) lib/active_support/notifications.rb:206:in `block in instrument'
web    | activesupport (7.0.8) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
web    | activesupport (7.0.8) lib/active_support/notifications.rb:206:in `instrument'
web    | actionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:66:in `process_action'
web    | actionpack (7.0.8) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
web    | searchkick (5.3.1) lib/searchkick/controller_runtime.rb:15:in `process_action'
web    | rescue_registry (1.0.0) lib/rescue_registry/controller.rb:24:in `process_action'
web    | activerecord (7.0.8) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
web    | actionpack (7.0.8) lib/abstract_controller/base.rb:151:in `process'
web    | actionview (7.0.8) lib/action_view/rendering.rb:39:in `process'
web    | actionpack (7.0.8) lib/action_controller/metal.rb:188:in `dispatch'
web    | actionpack (7.0.8) lib/action_controller/metal.rb:251:in `dispatch'
web    | actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
web    | actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:32:in `serve'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:50:in `block in serve'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `each'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `serve'
web    | actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:852:in `call'
web    | railties (7.0.8) lib/rails/engine.rb:530:in `call'
web    | railties (7.0.8) lib/rails/railtie.rb:226:in `public_send'
web    | railties (7.0.8) lib/rails/railtie.rb:226:in `method_missing'
web    | actionpack (7.0.8) lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
web    | actionpack (7.0.8) lib/action_dispatch/routing/mapper.rb:48:in `serve'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:50:in `block in serve'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `each'
web    | actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `serve'
web    | actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:852:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/static.rb:23:in `call'
web    | rack (2.2.9) lib/rack/session/abstract/id.rb:266:in `context'
web    | rack (2.2.9) lib/rack/session/abstract/id.rb:260:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/cookies.rb:704:in `call'
web    | rack (2.2.9) lib/rack/method_override.rb:24:in `call'
web    | warden (1.2.9) lib/warden/manager.rb:36:in `block in call'
web    | warden (1.2.9) lib/warden/manager.rb:34:in `catch'
web    | warden (1.2.9) lib/warden/manager.rb:34:in `call'
web    | rack (2.2.9) lib/rack/static.rb:161:in `call'
web    | rack (2.2.9) lib/rack/static.rb:161:in `call'
web    | rack (2.2.9) lib/rack/static.rb:161:in `call'
web    | rack (2.2.9) lib/rack/etag.rb:27:in `call'
web    | rack (2.2.9) lib/rack/conditional_get.rb:27:in `call'
web    | rack (2.2.9) lib/rack/head.rb:12:in `call'
web    | activerecord (7.0.8) lib/active_record/migration.rb:638:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
web    | activesupport (7.0.8) lib/active_support/callbacks.rb:99:in `run_callbacks'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'
web    | rescue_registry (1.0.0) lib/rescue_registry/action_dispatch/show_exceptions.rb:11:in `call'
web    | rescue_registry (1.0.0) lib/rescue_registry/reset_context.rb:9:in `call'
web    | railties (7.0.8) lib/rails/rack/logger.rb:40:in `call_app'
web    | railties (7.0.8) lib/rails/rack/logger.rb:25:in `block in call'
web    | activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `block in tagged'
web    | activesupport (7.0.8) lib/active_support/tagged_logging.rb:37:in `tagged'
web    | activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `tagged'
web    | railties (7.0.8) lib/rails/rack/logger.rb:25:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
web    | request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/request_id.rb:26:in `call'
web    | rack (2.2.9) lib/rack/runtime.rb:22:in `call'
web    | activesupport (7.0.8) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/static.rb:23:in `call'
web    | rack (2.2.9) lib/rack/sendfile.rb:110:in `call'
web    | actionpack (7.0.8) lib/action_dispatch/middleware/host_authorization.rb:138:in `call'
web    | rack-cors (2.0.1) lib/rack/cors.rb:102:in `call'
web    | railties (7.0.8) lib/rails/engine.rb:530:in `call'
web    | puma (6.4.1) lib/puma/configuration.rb:272:in `call'
web    | puma (6.4.1) lib/puma/request.rb:100:in `block in handle_request'
web    | puma (6.4.1) lib/puma/thread_pool.rb:378:in `with_force_shutdown'
web    | puma (6.4.1) lib/puma/request.rb:99:in `handle_request'
web    | puma (6.4.1) lib/puma/server.rb:464:in `process_client'
web    | puma (6.4.1) lib/puma/server.rb:245:in `block in run'
web    | puma (6.4.1) lib/puma/thread_pool.rb:155:in `block in spawn_thread'

Steps to Reproduce

Steps to reproduce the behavior:

  1. Add this configuration '...'
  2. Go to '...'
  3. Click on '....'
  4. Scroll down to '....'
  5. See error

Expected behavior & Actual behavior

Expected behaviour is that avo should load, instead I can't load anything.

Models and resource files

System configuration

Avo version: 3.7.4

Rails version: 7.0.8

Ruby version: ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [arm64-darwin22]

License type:

Are you using Avo monkey patches, overriding views or view components?

Screenshots or screen recordings

Additional context

I have managed to add a temporary fix for now, by monkey patching the Avo::Licensing::HQ class and changing the cache_response method to this:

def cache_response(response: nil, time: CACHE_TIME)
  response = normalize_response response

  response.merge!(
    expiry: time,
    fetched_at: Time.now,
    **payload
  ).stringify_keys!

  begin
    cache_store.write(self.class.cache_key, response, expires_in: time)
  rescue TypeError => e
  end

  response
end

So its not hugely impacting me, but this does mean that the response is not cached and I'm constantly pinging the license check server which slows things down.

This is the output when I inspect the response

{"id"=>"pro", "valid"=>true, "payload"=>{"signed_request"=>"REDACTED"}, "expiry"=>21600, "fetched_at"=>2024-05-22 10:17:23.687987 +1200, "license"=>"pro", "license_key"=>"REDACTED", "avo_version"=>"3.7.4", "rails_version"=>"7.0.8", "ruby_version"=>"3.3.0", "environment"=>"development", "ip"=>"127.0.0.1", "host"=>"localhost", "port"=>8000, "app_name"=>"REDACTED"}

Impact

Urgency

adrianthedev commented 4 months ago

Hey @Reizar,

Did you do any kind of updates to your caching infrastructure? Or maybe a ruby upgrade? Maybe the Marshal class changed somehow? Another thing I can think of is an HTTParty upgrade?

I'm don't think this should just malfunction like this all of the sudden.

Please try to confirm that the response is the thing that can't be marshalled and cached.


      def cache_response(response: nil, time: CACHE_TIME)
        response = normalize_response response

        response.merge!(
          expiry: time,
          fetched_at: Time.now,
          **payload
        ).stringify_keys!

        cache_store.write(self.class.cache_key, 
            response, # check to see if the stacktrace points to this line
            expires_in: time
        )

        response
      end

I don't want you to run with an un-cached license check so I want to fix this ASAP.

Reizar commented 4 months ago

Hi @adrianthedev,

Changed out the code and the stacktrace pointed to this line: cache_store.write(self.class.cache_key,.

However, I tried changing the self.class.cache_key variable used with the hardcoded string: "avo.hq-3-7-4.response" and the error still happened.

I did lots of experimenting, and the issue goes away if I call .deep_dup on the response hash. Tried inspecting and it looks to just be a regular hash, can't find any reason why it should be treated as a singleton.

Haven't changed out caching infrastructure, we don't really cache at the moment, so its still just configured as ActiveSupport::Cache::MemoryStore. Haven't changed out ruby version either. Could potentially be an upgrade of HTTParty though.

Thanks

github-actions[bot] commented 4 months ago

This issue has been marked as stale because there was no activity for the past 15 days.

adrianthedev commented 4 months ago

@Reizar can you try to update rails? Maybe there's something wrong with 7.0.8...

github-actions[bot] commented 3 months ago

This issue has been marked as stale because there was no activity for the past 15 days.

github-actions[bot] commented 2 months ago

Closing this because there was no activity for the past 15 days. Feel free to reopen if new information pops up ✌️