Bug #18005
Updated by Ward Vandewege over 2 years ago
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):
<pre>
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}
</pre>
The corresponding backtrace in the rails log:
<pre>
{
"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)"
}
</pre>
Note that the request id from the controller log (req-1lpuf064itirjfaslvcm) is nowhere to be found in the rails api log (@request_id: null@). log. 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.