Project

General

Profile

Actions
Copy link

Bug #18005

closed

[api] collection versioning regression

Added by Ward Vandewege over 2 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Lucas Di Pentima
Category:
API
Target version:
2021-08-18 sprint
Story points:
-
Release:
Arvados 2.2.2
Release relationship:
Auto

Description

I am seeing an "undefined method `each_line` for nil:NilClass error on ce8i5 when trying to add a new property to a collection without any properties (I used wb2):

Aug 10 15:49:36 api.ce8i5.arvadosapi.com arvados-controller[22796]: {"PID":22796,"RequestID":"req-1lpuf064itirjfaslvcm","level":"info","msg":"request","remoteAddr":"127.0.0.1:40238","reqBytes":86,"reqForwardedFor":"207.180.129.25","reqHost":"ce8i5.arvadosapi.com","reqMethod":"PUT","reqPath":"arvados/v1/collections/ce8i5-4zz18-k74yj38bjtguqg4","reqQuery":"","time":"2021-08-10T15:49:36.212264450Z"}
Aug 10 15:49:36 api.ce8i5.arvadosapi.com arvados-controller[22796]: {"PID":22796,"RequestID":"req-1lpuf064itirjfaslvcm","level":"info","msg":"response","remoteAddr":"127.0.0.1:40238","reqBytes":86,"reqForwardedFor":"207.180.129.25","reqHost":"ce8i5.arvadosapi.com","reqMethod":"PUT","reqPath":"arvados/v1/collections/ce8i5-4zz18-k74yj38bjtguqg4","reqQuery":"","respBody":"{\"errors\":[\"//railsapi.internal/arvados/v1/collections/ce8i5-4zz18-k74yj38bjtguqg4: 422 Unprocessable Entity: #\\u003cNoMethodError: undefined method `each_line' for nil:NilClass\\u003e (req-1lpuf064itirjfaslvcm)\"]}\n","respBytes":214,"respStatus":"Unprocessable Entity","respStatusCode":422,"time":"2021-08-10T15:49:36.242228716Z","timeToStatus":0.029935,"timeTotal":0.029955,"timeWriteBody":0.000020}

The corresponding backtrace in the rails log:

{
  "method": "PATCH",
  "path": "/arvados/v1/collections/ce8i5-4zz18-k74yj38bjtguqg4",
  "format": "html",
  "controller": "Arvados::V1::CollectionsController",
  "action": "update",
  "status": 422,
  "duration": 20.94,
  "view": 0.31,
  "db": 6.58,
  "request_id": null,
  "client_ipaddr": "127.0.0.1",
  "client_auth": "ce8i5-gj3su-cihrx35dbfrjoiy",
  "exception": "#<NoMethodError: undefined method `each_line' for nil:NilClass>",
  "exception_backtrace": "/var/www/arvados-api/current/app/models/collection.rb:462:in `each_manifest_locator'
/var/www/arvados-api/current/app/models/collection.rb:154:in `strip_signatures_and_update_replication_confirmed'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:426:in `block in make_lambda'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:605:in `catch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:605:in `block in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:199:in `block in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:513:in `block in invoke_before'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:513:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:513:in `invoke_before'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:131:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:816:in `_run_validation_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activemodel-5.2.6/lib/active_model/validations/callbacks.rb:118:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activemodel-5.2.6/lib/active_model/validations.rb:339:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/validations.rb:67:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/validations.rb:84:in `perform_validations'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/validations.rb:46:in `save'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:265:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:212:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:310:in `block in save'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:309:in `save'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/suppressor.rb:44:in `save'
/var/www/arvados-api/current/app/models/collection.rb:301:in `block (4 levels) in manage_versioning'
/var/www/arvados-api/current/lib/current_api_client.rb:138:in `block in act_as_system_user'
/var/www/arvados-api/current/lib/current_api_client.rb:149:in `act_as_user'
/var/www/arvados-api/current/lib/current_api_client.rb:137:in `act_as_system_user'
/var/www/arvados-api/current/app/models/collection.rb:300:in `block (3 levels) in manage_versioning'
/var/www/arvados-api/current/lib/arvados_model_updates.rb:32:in `leave_modified_at_alone'
/var/www/arvados-api/current/app/models/collection.rb:299:in `block (2 levels) in manage_versioning'
/var/www/arvados-api/current/lib/arvados_model_updates.rb:16:in `leave_modified_by_user_alone'
/var/www/arvados-api/current/app/models/collection.rb:298:in `block in manage_versioning'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/locking/pessimistic.rb:84:in `block in with_lock'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:265:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:212:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:301:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/locking/pessimistic.rb:82:in `with_lock'
/var/www/arvados-api/current/app/models/collection.rb:268:in `manage_versioning'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:136:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:816:in `_run_update_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/callbacks.rb:350:in `_update_record'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/timestamp.rb:114:in `_update_record'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/persistence.rb:705:in `create_or_update'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/callbacks.rb:342:in `block in create_or_update'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:132:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/callbacks.rb:342:in `create_or_update'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/persistence.rb:308:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/validations.rb:52:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:315:in `block in save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:265:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:212:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:315:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/suppressor.rb:48:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/persistence.rb:441:in `block in update!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:212:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/persistence.rb:439:in `update!'
/var/www/arvados-api/current/app/controllers/application_controller.rb:121:in `update'
/var/www/arvados-api/current/app/controllers/arvados/v1/collections_controller.rb:51:in `update'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/abstract_controller/base.rb:194:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/rendering.rb:30:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/var/www/arvados-api/current/app/controllers/application_controller.rb:423:in `block in set_current_request_id'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:28:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:71:in `tagged'
/var/www/arvados-api/current/app/controllers/application_controller.rb:422:in `set_current_request_id'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:136:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/abstract_controller/callbacks.rb:41:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/rescue.rb:22:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/notifications.rb:168:in `block in instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/notifications.rb:168:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activerecord-5.2.6/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/abstract_controller/base.rb:134:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionview-5.2.6/lib/action_view/rendering.rb:32:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal.rb:191:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_controller/metal.rb:252:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/journey/router.rb:35:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/journey/router.rb:35:in `serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/routing/route_set.rb:840:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/callbacks.rb:98:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/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'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.2.6/lib/rails/rack/logger.rb:26:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:28:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/tagged_logging.rb:71:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.2.6/lib/rails/rack/logger.rb:26:in `call'
/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'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/activesupport-5.2.6/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/executor.rb:14:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/actionpack-5.2.6/lib/action_dispatch/middleware/ssl.rb:80:in `call'
/var/www/arvados-api/current/app/middlewares/arvados_api_token.rb:67:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.2.6/lib/rails/engine.rb:524:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.2.6/lib/rails/railtie.rb:190:in `public_send'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.5.0/gems/railties-5.2.6/lib/rails/railtie.rb:190:in `method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:157: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:416: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'
",
  "params": {
    "collection": "{\"preserve_version\":true,\"properties\":{\"IDTAGANIMALS\":\"IDVALANIMALS3\"}}" 
  },
  "@timestamp": "2021-08-10T15:49:36.240979904Z",
  "@version": "1",
  "message": "[422] PATCH /arvados/v1/collections/ce8i5-4zz18-k74yj38bjtguqg4 (Arvados::V1::CollectionsController#update)" 
}

Note that the request id from the controller log (req-1lpuf064itirjfaslvcm) is nowhere to be found in the rails api log (request_id: null). Why? => tracking that as a separate bug in #18008.

On tordo, versioning is disabled, and I can't reproduce the problem. But when I set enable Collections/CollectionVersioning on tordo, I see the same problem. This seems to be a bug/regression in our collection versioning code.

More data: testing against 2.2.1 (latest release), with collection versioning enabled, the bug does not exist.

Subtasks 1 (0 open — 1 closed)

Task #18012: Review 18005-collection-versioning-regressionResolvedWard Vandewege08/11/2021Actions

Related issues

Related to Arvados - Bug #18008: [api] reqid not always being recorded in the api server logNewActions
Actions
Copy link
 #1

Updated by Ward Vandewege over 2 years ago

  • Description updated (diff)
Actions
Copy link
 #2

Updated by Lucas Di Pentima over 2 years ago

  • Assigned To set to Lucas Di Pentima
  • Status changed from New to In Progress
Actions
Copy link
 #3

Updated by Ward Vandewege over 2 years ago

The error is in this function:

  def strip_signatures_and_update_replication_confirmed
    if self.manifest_text_changed?
      in_old_manifest = {}
      if not self.replication_confirmed.nil?
        self.class.each_manifest_locator(manifest_text_was) do |match|
          in_old_manifest[match[1]] = true
        end
      end

Since we recently started updating replication_confirmed, this is the first time we are hitting this code path.

Actions
Copy link
 #4

Updated by Ward Vandewege over 2 years ago

  • Related to Bug #18008: [api] reqid not always being recorded in the api server log added
Actions
Copy link
 #5

Updated by Ward Vandewege over 2 years ago

  • Description updated (diff)
Actions
Copy link
 #6

Updated by Lucas Di Pentima over 2 years ago

Updates at c3481a6 - branch 18005-collection-versioning-regression
Test run: developer-run-tests: #2633

  • Updates existing test, exposing the problem: when keep-balance updates the replication_confirmed field on a collection and a versionable update happens, the new collection version record will appear to have its manifest_text field changed with manifest_text_was returning nil, producing the error.
  • Fixes the bug.
Actions
Copy link
 #7

Updated by Ward Vandewege over 2 years ago

Lucas Di Pentima wrote:

Updates at c3481a6 - branch 18005-collection-versioning-regression
Test run: developer-run-tests: #2633

  • Updates existing test, exposing the problem: when keep-balance updates the replication_confirmed field on a collection and a versionable update happens, the new collection version record will appear to have its manifest_text field changed with manifest_text_was returning nil, producing the error.
  • Fixes the bug.

LGTM, thanks!

Actions
Copy link
 #8

Updated by Lucas Di Pentima over 2 years ago

  • Release set to 41
  • Target version set to 2021-08-18 sprint
  • Status changed from In Progress to Resolved
  • Category set to API
Actions
Copy link

Also available in: Atom PDF