-
Type:
Bug
-
Resolution: Fixed
-
Priority:
Major - P3
-
None
-
Affects Version/s: 2.6.0
-
Component/s: Spec Comp, Transactions
-
3
Spec reference: https://github.com/mongodb/specifications/blob/master/source/transactions/transactions.rst#error-labels
I cannot see any code in the driver implementing this functionality.
The transaction spec test runner, in spec/support/transactions/operation.rb, has this code:
rescue Mongo::Error::OperationFailure => e
err_doc = e.instance_variable_get(:@result).send(:first_document)
{
'errorCodeName' => err_doc['codeName'] || err_doc['writeConcernError']['codeName'],
'errorContains' => e.message,
'errorLabels' => (e.instance_variable_get(:@labels) || []) + (err_doc['errorLabels'] || [])
}
... which takes errorLabels off the response and puts them into the "actual" result, even though the actual exception instance raised by the driver doesn't have any labels returned by the server.
Original report:
We are using Ruby and Mongoid on a replica set db setup and we are updating multiple documents in a transaction within a session.
When we are doing the above operation multiple times across multiple application threads, we are getting error code 251.
We are respecting the instructions specified here: https://docs.mongodb.com/master/core/transactions/ - under the Retry Transaction section, ruby code
and here: https://docs.mongodb.com/mongoid/master/tutorials/mongoid-transactions/
and we are trying to retry if the commit fails and there is a TransientTransactionError label.
After retrying the commit all works.
Unfortunately, we have noticed that upon catching the error, it presents no labels, like specified by the ruby code example. `e.label?(Mongo::Error::TRANSIENT_TRANSACTION_ERROR_LABEL)` (and it should)
The code below present the debugging output that we generated for this:
msg = error.message rescue ''
code = error.code rescue ''
code_name = error.code_name rescue ''
replies = error.instance_variable_get(:@result).replies.inspect rescue ''
result = error.instance_variable_get(:@result).inspect rescue ''
labels = error.instance_variable_get(:@labels).inspect rescue ''
classy = error.class.name rescue ''
transient = error.label?(Mongo::Error::TRANSIENT_TRANSACTION_ERROR_LABEL) rescue ''
unknown = error.label?(Mongo::Error::UNKNOWN_TRANSACTION_COMMIT_RESULT_LABEL) rescue ''
response_first_document = error.instance_variable_get(:@result).send(:first_document) rescue ''
error_labels = response_first_document['errorLabels'] rescue ''
error_debug = { message: msg,
code: code,
code_name: code_name,
class: classy,
replies: replies,
result: result,
labels: labels,
transient: transient,
unknown: unknown,
scenario: message,
backtrace: error.backtrace.join(','),
response_first_document: response_first_document,
error_labels: error_labels
Below is what the abve output actually generates:
"message":"Transaction 2 has been aborted. (251)","code":251,"code_name":"NoSuchTransaction","class":"Mongo::Error::OperationFailure","replies":"[#\u003cMongo::Protocol::Msg:0x005574656347f8 @flags=[], @sections=[{\"errorLabels\"=\u003e[\"TransientTransactionError\"], \"operationTime\"=\u003e#\u003cBSON::Timestamp:0x00557465634550 @seconds=1541097158, @increment=1\u003e, \"ok\"=\u003e0.0, \"errmsg\"=\u003e\"Transaction 2 has been aborted.\", \"code\"=\u003e251, \"codeName\"=\u003e\"NoSuchTransaction\", \"$clusterTime\"=\u003e{\"clusterTime\"=\u003e#\u003cBSON::Timestamp:0x00557465634230 @seconds=1541097158, @increment=1\u003e, \"signature\"=\u003e{\"hash\"=\u003e\u003cBSON::Binary:0x46979202785340 type=generic data=0x0000000000000000...\u003e, \"keyId\"=\u003e0}}}]\u003e]","result":"#\u003cMongo::Operation::Result:0x46979202800280 documents=[{\"errorLabels\"=\u003e[\"TransientTransactionError\"], \"operationTime\"=\u003e#\u003cBSON::Timestamp:0x00557465634550 @seconds=1541097158, @increment=1\u003e, \"ok\"=\u003e0.0, \"errmsg\"=\u003e\"Transaction 2 has been aborted.\", \"code\"=\u003e251, \"codeName\"=\u003e\"NoSuchTransaction\", \"$clusterTime\"=\u003e{\"clusterTime\"=\u003e#\u003cBSON::Timestamp:0x00557465634230 @seconds=1541097158, @increment=1\u003e, \"signature\"=\u003e{\"hash\"=\u003e\u003cBSON::Binary:0x46979202785340 type=generic data=0x0000000000000000...\u003e, \"keyId\"=\u003e0}}}]\u003e","labels":"[]","transient":false,"unknown":false,"scenario":"Error during commit, checking for unknown transaction label...","backtrace":"/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/operation/result.rb:267:in `raise_operation_failure',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/operation/result.rb:263:in `validate!',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/operation/command/op_msg.rb:42:in `execute',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/operation/command.rb:41:in `execute',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/session.rb:549:in `block in commit_transaction',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/retryable.rb:117:in `write_with_retry',/opt/api/shared/bundle/ruby/2.4.0/gems/mongo-2.6.2/lib/mongo/session.rb:543:in `commit_transaction',/opt/api/releases/20181101175712/lib/mongo_cache.rb:93:in `commit_with_retry',/opt/api/releases/20181101175712/app/services/join_syndicate.rb:47:in `update_join_info',/opt/api/releases/20181101175712/app/services/join_syndicate.rb:19:in `block (2 levels) in perform',/opt/api/releases/20181101175712/lib/mongo_cache.rb:71:in `run_transaction_with_retry',/opt/api/releases/20181101175712/app/services/join_syndicate.rb:19:in `block in perform',/opt/api/shared/bundle/ruby/2.4.0/bundler/gems/mongoid-700a7a7cd360/lib/mongoid/clients/sessions.rb:46:in `with_session',/opt/api/releases/20181101175712/app/services/join_syndicate.rb:16:in `perform',/opt/api/releases/20181101175712/app/controllers/v2/syndicate_portions_controller.rb:56:in `create',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:186:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/instruments/action_controller_rails_3_rails4.rb:72:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/rendering.rb:30:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:20:in `block in process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks',/opt/api/shared/bundle/ruby/2.4.0/gems/sentry-raven-2.7.4/lib/raven/integrations/rails/controller_transaction.rb:7:in `block in included',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:19:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/rescue.rb:20:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `block in instrument',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `instrument',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:30:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal/params_wrapper.rb:252:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/activerecord-5.1.6/lib/active_record/railties/controller_runtime.rb:22:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/instruments/action_controller_rails_3_rails4.rb:83:in `process_action',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:124:in `process',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal.rb:189:in `dispatch',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_controller/metal.rb:253:in `dispatch',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:49:in `dispatch',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:31:in `serve',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/routing/mapper.rb:16:in `block in \u003cclass:Constraints\u003e',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/routing/mapper.rb:46:in `serve',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:50:in `block in serve',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33:in `each',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33:in `serve',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:844:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/instruments/rails_router.rb:29:in `call_with_scout_instruments',/opt/api/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:36:in `block in call',/opt/api/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `catch',/opt/api/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/middleware.rb:17:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/versionist-1.7.0/lib/versionist/middleware.rb:39:in `_call',/opt/api/shared/bundle/ruby/2.4.0/gems/versionist-1.7.0/lib/versionist/middleware.rb:17:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/etag.rb:25:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/conditional_get.rb:38:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/head.rb:12:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:97:in `run_callbacks',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:24:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app',/opt/api/shared/bundle/ruby/2.4.0/gems/railties-5.1.6/lib/rails/rack/logger.rb:24:in `block in call',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `block in tagged',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:26:in `tagged',/opt/api/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `tagged',/opt/api/shared/bundle/ruby/2.4.0/gems/railties-5.1.6/lib/rails/rack/logger.rb:24:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/remote_ip.rb:79:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/request_id.rb:25:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/runtime.rb:22:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:123:in `block in call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-timeout-0.5.1/lib/rack/timeout/support/timeout.rb:19:in `timeout',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:122:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/executor.rb:12:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/sentry-raven-2.7.4/lib/raven/integrations/rack.rb:51:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/instruments/middleware_summary.rb:58:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/railties-5.1.6/lib/rails/engine.rb:522:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/common_logger.rb:33:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/chunked.rb:54:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/content_length.rb:15:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:606:in `process_client',/opt/api/shared/bundle/ruby/2.4.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:701:in `worker_loop',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/server_integrations/unicorn.rb:52:in `call',/opt/api/shared/bundle/ruby/2.4.0/gems/scout_apm-2.4.19/lib/scout_apm/server_integrations/unicorn.rb:52:in `block (2 levels) in install',/opt/api/shared/bundle/ruby/2.4.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:549:in `spawn_missing_workers',/opt/api/shared/bundle/ruby/2.4.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:142:in `start',/opt/api/shared/bundle/ruby/2.4.0/gems/unicorn-5.4.1/bin/unicorn:126:in `\u003ctop (required)\u003e',/opt/api/shared/bundle/ruby/2.4.0/bin/unicorn:23:in `load',/opt/api/shared/bundle/ruby/2.4.0/bin/unicorn:23:in `\u003cmain\u003e'","response_first_document":{"errorLabels":["TransientTransactionError"],"operationTime":{"$timestamp":{"t":1541097158,"i":1}},"ok":0.0,"errmsg":"Transaction 2 has been aborted.","code":251,"codeName":"NoSuchTransaction","$clusterTime":{"clusterTime":{"$timestamp":{"t":1541097158,"i":1}},"signature":{"hash":{"$binary":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=\n","$type":"generic"},"keyId":0}}},"error_labels":["TransientTransactionError"],"@timestamp":"2018-11-01T18:32:39.855+00:00","@version":"1","severity":"ERROR","host":"api-08.tote-slave.stg.ovh.local"}
In short terms, we were expecting a `Mongo::Error` to have the "TransientTransactionError" passed on to it, and it doesn't.
I think something like the below code is missing from the commit transaction logic.
if err_doc['errorLabels'].include?(Mongo::Error::TRANSIENT_TRANSACTION_ERROR_LABEL)
e.send(:add_label, Mongo::Error::TRANSIENT_TRANSACTION_ERROR_LABEL)
end
R