Replication controller occasionally returns a 422

[mikejritter]

When completing a replication my client has seen the server return a 422 with the response body

{"status":"422","error":"Unprocessable Entity"}

According to TDR they saw an ActiveRecord exception in the log

ActiveRecord::RecordInvalid (Validation failed: Bag has already been taken):
 app/services/replication_transfer_updater.rb:137:in `add_replicating_node'
 app/services/replication_transfer_updater.rb:129:in `update'
 app/services/replication_transfer_updater.rb:10:in `update'
 app/controllers/replication_transfers_controller.rb:62:in `update'

There still needs to be some investigation as to what is going on, but at a first glance it seems like the error is coming from the replicating_nodes relationship. i.e. chron is already a replicating node of the bag, so an error is thrown when trying to add chron to the set. A good first step will be to look in to app/services/replication_transfer_updater.rb.

I should add that the replication itself is still updated successfully despite the 422 response.

[mikejritter]

I was actually able to confirm this pretty easily using the rails console (truncated for brevity).

irb(main):003:0> b = Bag.find_by(uuid: "a32e18e4-8bf4-4bc0-9e98-3f51da9ea2a1")
irb(main):004:0>  n = Node.find_by(namespace: "chron")
irb(main):005:0> b.replicating_nodes << n
ActiveRecord::RecordInvalid: Validation failed: Bag has already been taken

I'm going to add a clause in the replication_transfer_updater and run a replication against it.

[mikejritter]

Checking if the replicating_nodes includes a node before adding it seems to work well enough in my dev environment. Going to create a PR with the changes.

[dazza-codes]

Confirmed a similar error on trying to update the stored: true attribute on a repl-transfer from TDR to SDR. Somewhere in the TDR-dev node dpn-server/log/production.log there could be an error logged corresponding to the error logged in the SDR-dev node, i.e.

2017-01-07T20:00:34.955Z 16855 TID-o74f0 WARN: {"context":"Job raised exception”,  ... "created_at":1483819216.5947845,"enqueued_at":1483819216.5948524,"error_message":"Failed to update replication: {:status=>\"422\", :error=>\"Unprocessable Entity\”}"

This was for "replication_id":"f09cf78c-8da1-478e-9b9e-c930e832b539". Despite the error, the replication now has the correct attr:value pairs.

The TDR-dev node logs also had the ActiveRecord:RecordInvalid error, i.e.

I, [2017-01-07T14:00:34.930155 #2014]  INFO -- : {"method":"PUT","path":"/api-v2/replicate/f09cf78c-8da1-478e-9b9e-c930e832b539","format":"*/*","controller":"ReplicationTransfersController","action":"update","status":422,"error":"ActiveRecord::RecordInvalid: Validation failed: Bag has already been taken","duration":32.32,"view":0.0,"db":4.52,"params":{"replication_id":"f09cf78c-8da1-478e-9b9e-c930e832b539","fixity_nonce":null,"fixity_value":"2c1506a54eb690838e5c9be8b9b1eecad2272e6b1e41668b1eff99e63b9d7bcc","cancel_reason":null,"cancel_reason_detail":null,"link":"sdr@rest-dev.lib.utexas.edu:/home/sdr/staging/f7876ef3-7f4e-4a89-8629-fd766f8b59a7.tar","created_at":"2017-01-06T22:29:13Z","updated_at":"2017-01-07T19:00:37Z","store_requested":true,"stored":true,"cancelled":false,"bag":"f7876ef3-7f4e-4a89-8629-fd766f8b59a7","fixity_algorithm":"sha256","protocol":"rsync","from_node":"tdr","to_node":"sdr","replication_transfer":{"link":"sdr@rest-dev.lib.utexas.edu:/home/sdr/staging/f7876ef3-7f4e-4a89-8629-fd766f8b59a7.tar","fixity_nonce":null,"fixity_value":"2c1506a54eb690838e5c9be8b9b1eecad2272e6b1e41668b1eff99e63b9d7bcc","created_at":"2017-01-06T22:29:13Z","updated_at":"2017-01-07T19:00:37Z","replication_id":"f09cf78c-8da1-478e-9b9e-c930e832b539","store_requested":true,"stored":true,"cancelled":false,"cancel_reason":null,"cancel_reason_detail":null}},"@timestamp":"2017-01-07T20:00:34.929Z","@version":"1","message":"[422] PUT /api-v2/replicate/f09cf78c-8da1-478e-9b9e-c930e832b539 (ReplicationTransfersController#update)"}
F, [2017-01-07T14:00:34.930896 #2014] FATAL -- :
ActiveRecord::RecordInvalid (Validation failed: Bag has already been taken):
  app/services/replication_transfer_updater.rb:140:in `add_replicating_node'
  app/services/replication_transfer_updater.rb:130:in `update'
  app/services/replication_transfer_updater.rb:11:in `update'
  app/controllers/replication_transfers_controller.rb:62:in `update'

[dazza-codes]

This should be resolved by #151 - available in release tag v2.0.1