Project

General

Profile

Actions
Copy link

Bug #15716

closed

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

Added by Ward Vandewege about 5 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Lucas Di Pentima
Category:
API
Target version:
2019-10-23 Sprint
Start date:
10/18/2019
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
-
Release:
Arvados 2.0 - Early 2020
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 1 (0 open — 1 closed)

Task #15735: Review 15716-api-keepservice-list-fixResolvedLucas Di Pentima10/18/2019

Actions
Actions
Copy link
 #1

Updated by Ward Vandewege about 5 years ago

  • Description updated (diff)
Actions
Copy link
 #2

Updated by Tom Clegg about 5 years 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.

Actions
Copy link
 #3

Updated by Peter Amstutz about 5 years 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.

Actions
Copy link
 #4

Updated by Lucas Di Pentima about 5 years ago

  • Category set to API
  • Assigned To set to Lucas Di Pentima
  • Target version set to 2019-10-23 Sprint
Actions
Copy link
 #5

Updated by Lucas Di Pentima about 5 years ago

  • Status changed from New to In Progress
Actions
Copy link
 #6

Updated by Lucas Di Pentima about 5 years 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
Actions
Copy link
 #7

Updated by Lucas Di Pentima about 5 years 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.

Actions
Copy link
 #8

Updated by Lucas Di Pentima about 5 years 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.

Actions
Copy link
 #9

Updated by Tom Clegg about 5 years ago

Aha! Thanks for figuring this out. LGTM.

Actions
Copy link
 #10

Updated by Lucas Di Pentima about 5 years ago

  • Status changed from In Progress to Resolved
Actions
Copy link
 #12

Updated by Lucas Di Pentima about 5 years 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

Actions
Copy link
 #13

Updated by Peter Amstutz almost 5 years ago

  • Release set to 22
Actions
Copy link

Also available in: Atom PDF