Bug #15716

[api] deleting all keep_service records results in 422 error on subsequent request for keep_service list

Added by Ward Vandewege 9 months ago. Updated 6 months ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
API
Target version:
Start date:
10/18/2019
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
-
Release relationship:
Auto

Description

Following the instructions in the upgrading document, I'm converting 4xphq's keepstores to use config.yml. That is complete, so I deleted the the keep_service records in the database as per the instructions.

Then I asked for the list of keep_services again:

4xphq:~# arv --format=uuid keep_service list
Error: #<NameError: undefined local variable or method `system_user_uuid' for #<Class:0x0000561d6166a420>> (req-1h986nf9bub38yd9cslp)

Keep-balance is getting the same error and aborts its run because it can't get the list of keep services.

The stacktrace is:

#<NameError: undefined local variable or method `system_user_uuid' for #<Class:0x0000561d6166a420>>

/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/dynamic_matchers.rb:21:in `method_missing'
/data/var-www/arvados-api/current/app/models/keep_service.rb:50:in `from_config'
/data/var-www/arvados-api/current/app/models/keep_service.rb:28:in `all'
/data/var-www/arvados-api/current/app/models/keep_service.rb:35:in `where'
/data/var-www/arvados-api/current/app/controllers/arvados/v1/keep_services_controller.rb:21:in `accessible'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:188:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/data/var-www/arvados-api/current/app/controllers/application_controller.rb:423:in `block in set_current_request_id'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'
/data/var-www/arvados-api/current/app/controllers/application_controller.rb:422:in `set_current_request_id'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:285:in `block in halting'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:447:in `block in around'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:19:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rescue.rb:20:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `block in instrument'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `instrument'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:126:in `process'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionview-5.0.7.2/lib/action_view/rendering.rb:30:in `process'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:190:in `dispatch'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:262:in `dispatch'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:39:in `block in serve'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `each'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `serve'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:727:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:186:in `call!'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:164:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/omniauth-1.4.3/lib/omniauth/builder.rb:63:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/etag.rb:25:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/conditional_get.rb:25:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in `context'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:36:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `block in call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/runtime.rb:22:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.0.7.2/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/ssl.rb:84:in `call'
/data/var-www/arvados-api/current/app/middlewares/arvados_api_token.rb:66:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.0.7.2/lib/rails/engine.rb:522:in `call'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `public_send'
/data/var-www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:149:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

Subtasks

Task #15735: Review 15716-api-keepservice-list-fixResolvedLucas Di Pentima

Associated revisions

Revision 49ceaf05
Added by Lucas Di Pentima 9 months ago

Merge branch '15716-api-keepservice-list-fix'
Closes #15716

History

#1 Updated by Ward Vandewege 9 months ago

  • Description updated (diff)

#2 Updated by Tom Clegg 9 months ago

It seems like the fix should be easy enough:

diff --git a/services/api/app/models/keep_service.rb b/services/api/app/models/keep_service.rb
index 60f263202..f76f5e47a 100644
--- a/services/api/app/models/keep_service.rb
+++ b/services/api/app/models/keep_service.rb
@@ -7,6 +7,7 @@ class KeepService < ArvadosModel
   include KindAndEtag
   include CommonApiTemplate
   extend DbCurrentTime
+  extend CurrentApiClient

   SERVER_START_TIME = db_current_time

But I'd really like to know why the test suite doesn't catch this.

Arvados::V1::KeepServicesControllerTest#test_report_configured_servers_if_db_is_empty definitely exercises the relevant call in from_config. If you change it to system_user_uuidx, the test fails.

#3 Updated by Peter Amstutz 9 months ago

I had to do the same thing in the user model at 65705937e9c86a4ee557a32b776745e4ae8e88db

I didn't track down the reason tests passed, but it seems like CurrentApiClient is imported into the test environment somewhere.

#4 Updated by Lucas Di Pentima 9 months ago

  • Category set to API
  • Assigned To set to Lucas Di Pentima
  • Target version set to 2019-10-23 Sprint

#5 Updated by Lucas Di Pentima 9 months ago

  • Status changed from New to In Progress

#6 Updated by Lucas Di Pentima 9 months ago

Findings:

  • ArvadosModel already includes CurrentApiClient and it's indeed listed on KeepService's .ancestors list
  • When running the rails console, I'm able to get the same error described in this report.
  • Asking the ancestor its public methods does list system_user_uuid (see below)
  • What I'm thinking is not that the test running environment has anything special but on the contrary the others environments are behaving differently.
  • My current lead is that when we upgraded to Rails 5 we had some issues with constant's autoloading that was disabled, not sure if this is the cause yet.
2.5.5 :020 > KeepService.system_user_uuid
Traceback (most recent call last):
        9: from bin/rails:9:in `<main>'
        8: from bin/rails:9:in `require'
        7: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/railties-5.0.7.2/lib/rails/commands.rb:18:in `<top (required)>'
        6: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/railties-5.0.7.2/lib/rails/commands/commands_tasks.rb:49:in `run_command!'
        5: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/railties-5.0.7.2/lib/rails/commands/commands_tasks.rb:78:in `console'
        4: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/railties-5.0.7.2/lib/rails/commands/console_helper.rb:9:in `start'
        3: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/railties-5.0.7.2/lib/rails/commands/console.rb:65:in `start'
        2: from (irb):20
        1: from /home/lucas/.rvm/gems/ruby-2.5.5@arvados-api/gems/activerecord-5.0.7.2/lib/active_record/dynamic_matchers.rb:21:in `method_missing'
NoMethodError (undefined method `system_user_uuid' for #<Class:0x000055ad0031a7b0>)
2.5.5 :021 > KeepService.ancestors[10]
 => CurrentApiClient 
2.5.5 :025 > KeepService.ancestors[10].public_instance_methods.include? :system_user_uuid
 => true

#7 Updated by Lucas Di Pentima 9 months ago

Disregard the above note. I was looking for the wrong methods.

What I've found is that the methods defined on the CurrentApiClient module at lib/current_api_client.rb are somehow imported as class methods directly on Object's superclass on the test environment, just like other from the mocha or byebug packages:

(byebug) Object.superclass.singleton_class.instance_methods.include? :system_user_uuid
true
(byebug) Object.superclass.singleton_class.instance_methods.include? :db_current_time
false
(byebug) Object.superclass.singleton_class.instance_methods.include? :byebug
true

On development and production environments, CurrentApiClient's methods aren't implicitly available as class methods.

It seems that this happens when Rails.application.initialize! is called at line 10 on services/api/config/environment.rb, nevertheless I think this is called on all environments, and only on "test" is misbehaving, so it's logical to think that there can be some setting enabling the behavior.

Another interesting point is that this happens only with lib/current_api_client.rb, and not others modules on lib/, so some module auto-load mechanism may be ruled out.

#8 Updated by Lucas Di Pentima 9 months ago

  • Release set to 27

Updates at f2d88ae - branch 15716-api-keepservice-list-fix
Test run: https://ci.curoverse.com/job/developer-run-tests/1601/
Fuse tests retry: https://ci.curoverse.com/job/developer-run-tests-services-fuse/1624/

By using the module's .included() hook I was able to see where the CurrentApiClient was being imported into the Object class.
The services/api/lib/tasks/symbols.rake file was the culprit, it seems that including modules from rake tasks is something we shouldn't do.
Fixing this issue exposed a missing import on the CommitsHelper module too.

#9 Updated by Tom Clegg 9 months ago

Aha! Thanks for figuring this out. LGTM.

#10 Updated by Lucas Di Pentima 9 months ago

  • Status changed from In Progress to Resolved

#12 Updated by Lucas Di Pentima 8 months ago

  • Release deleted (27)

Removed the assigned release because it fixes a problem that doesn't exist on the 1.4.x release and was introduced on #15311

#13 Updated by Peter Amstutz 6 months ago

  • Release set to 22

Also available in: Atom PDF