cloud_controller_ng Mysql transaction deadlock when running CATs

Issue

We're running CATs with SCF+Eirini. Occasionally they fail due to some transaction deadlock in Mysql.

Context

We run CAPI release 1.81. See more info about releases here

Steps to Reproduce

Deploy SCF with Eirini, according to instructions here
Run CATs with this config

Expected result

CATs should pass without any errors in cc logs

Current result

Sometimes they pass, sometimes they fail.

Here is the error:

{"timestamp":1560420022.9494345,"message":"Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction: UPDATE `buildpack_lifecycle_data` SET `droplet_guid` = NULL WHERE ((`droplet_guid` = '5aac7308-c5f7-45ac-9c89-c9437471af5c') AN
D (`id` != 3335)) LIMIT 1","log_level":"error","source":"cc.db","data":{"request_guid":"c317e409-5754-471d-a937-eb97a02eac80"},"thread_id":47442393915700,"fiber_id":47442368878680,"process_id":1,"file":"/var/vcap/packages/.src/4f233290b34ea859bfacecc196
e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/logging.rb","lineno":82,"method":"public_send"}

Here is the relevant stacktrace:

exception not translated: Sequel::SerializationFailure - Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction:
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `_query'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `block in query'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `handle_interrupt'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `query'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/adapters/mysql2.rb:137:in `block in _execute'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/logging.rb:43:in `log_connection_yield'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/adapters/mysql2.rb:132:in `_execute'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/adapters/utils/mysql_mysql2.rb:39:in `block in execute'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `block in synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/adapters/utils/mysql_mysql2.rb:39:in `execute'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/adapters/mysql2.rb:68:in `execute_dui'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/dataset/actions.rb:1094:in `execute_dui'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/dataset/actions.rb:868:in `update'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/associations.rb:2212:in `block (2 levels) in def_one_to_many'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1905:in `block in checked_transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:216:in `block in transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `block in synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:186:in `transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1905:in `checked_transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/associations.rb:2211:in `block in def_one_to_many'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/associations.rb:2616:in `_set_associated_object'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/associations.rb:2646:in `set_one_to_one_associated_object'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/model/associations.rb:2216:in `block in def_one_to_many'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/actions/droplet_create.rb:57:in `block in create_buildpack_droplet'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:245:in `_transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:220:in `block in transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `block in synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:253:in `synchronize'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:186:in `transaction'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/actions/droplet_create.rb:55:in `create_buildpack_droplet'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/controllers/runtime/stagings_controller.rb:137:in `create_droplet_from_build'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/controllers/runtime/stagings_controller.rb:132:in `droplet_from_build'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/controllers/runtime/stagings_controller.rb:112:in `upload_droplet'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/controllers/runtime/stagings_controller.rb:63:in `upload_package_droplet_mtls'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/app/controllers/base/base_controller.rb:86:in `dispatch'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/lib/cloud_controller/rest_controller/routes.rb:16:in `block in define_route'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1634:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1634:in `block in compile!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:992:in `block (3 levels) in route!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1011:in `route_eval'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:992:in`block (2 levels) in route!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1040:in `block in process_route'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1038:in `catch'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1038:in `process_route'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:990:in `block in route!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:989:in `each'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:989:in `route!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1097:in `block in dispatch!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `block in invoke'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `catch'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `invoke'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1094:in `dispatch!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:924:in `block in call!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `block in invoke'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `catch'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1076:in `invoke'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:924:in `call!'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:913:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/xss_header.rb:18:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/path_traversal.rb:16:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/json_csrf.rb:26:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/base.rb:50:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/base.rb:50:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-protection-2.0.5/lib/rack/protection/frame_options.rb:31:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/null_logger.rb:9:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:194:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/sinatra-2.0.5/lib/sinatra/base.rb:1957:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/urlmap.rb:68:in `block in call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `each'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/request_logs.rb:22:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/security_context_setter.rb:19:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/vcap_request_id.rb:15:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/cors.rb:49:in `call_app'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/cors.rb:14:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/cloud_controller_ng/middleware/request_metrics.rb:12:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/rack-2.0.7/lib/rack/builder.rb:153:in `call'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/thin-1.7.2/lib/thin/connection.rb:86:in `block in pre_process'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/thin-1.7.2/lib/thin/connection.rb:84:in `catch'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/thin-1.7.2/lib/thin/connection.rb:84:in `pre_process'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/thin-1.7.2/lib/thin/connection.rb:50:in `block in process'
/var/vcap/packages/.src/4f233290b34ea859bfacecc196e7c35541e4290e/gem_home/ruby/2.4.0/gems/eventmachine-1.0.9.1/lib/eventmachine.rb:1067:in `block in spawn_threadpool'

/cc @alex-slynko

Jun 13 '19 14:06 akshaymankar

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/166675813

The labels on this github issue will be updated when the story is started.

Jun 13 '19 14:06 cf-gitbot

Hi @akshaymankar and @alex-slynko,

We took a look at the logs for one of our long-running environments that runs cats frequently, and spotted the same error only a couple of times in the past few weeks. What we have found though is it originates from this endpoint POST /internal/v4/droplets/<droplet-guid>/upload?async=true after staging completes.

We don't have a SCF + Eirini environment easily available to us, so we were wondering if should could elaborate more on the differences between staging in Diego and Eirini to help us understand what might make this happen more often in this configuration. Like for example, does the Eirini stager retry these droplet uploads more frequently? Something else?