search

cloudfoundry / cloud_controller_ng

Cloud Foundry Cloud Controller
Apache License 2.0
191 stars 357 forks source link

Mysql transaction deadlock when running CATs #1374

Closed akshaymankar closed 8 months ago

akshaymankar commented 5 years ago

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

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

Expected result

  1. 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

cf-gitbot commented 5 years ago

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.

tcdowney commented 5 years ago

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?

cwlbraa commented 4 years ago

do y'all still have these deadlock issues? @akshaymankar

akshaymankar commented 4 years ago

I have since moved on from the team, @alex-slynko or @JulzDiverse might be able to help.

alex-slynko commented 4 years ago

We don't have any more deadlocks.

gdankov commented 4 years ago

Hello,

We encountered the issue again with the latest CAPI version 1.93.0.

Best regards, Georgi && @yulianedyalkova

moleske commented 8 months ago

k8s support was dropped, closing