Lockbox::DecryptionError (Decryption failed) when rotating

[herunan]

When I try to rotate the key I get Lockbox::DecryptionError (Decryption failed) (even in master, which helped in this issue)

Steps to reproduce:

1. I have a master key in place here: Rails.application.credentials.lockbox[:master_key]

2. Suppose it got leaked. I generate a new key: Lockbox.generate_key

3. I store it as the new master_key here: Rails.application.credentials.lockbox[:master_key]

4. The old one is now old_master_key here: Rails.application.credentials.lockbox[:old_master_key]

5. I modify my User model with: encrypts :email, :unconfirmed_email, previous_versions: [{master_key: Rails.application.credentials.lockbox[:old_master_key]}]

6. I run Lockbox.rotate(User, attributes: [:email, :unconfirmed_email])

7. I get Lockbox::DecryptionError (Decryption failed)

[ankane]

Hey @herunan, those steps look correct. A few questions:

1. Where are you seeing the error (console, web server)? Have you tried restarting to make sure the new credentials and code changes have been picked up?
2. Any chance there's another attribute on the model that's not being rotated and causing the error?

[herunan]

1. Seeing it in the console. Running development environment locally on master.
2. Those are the only two attributes. There are no unconfirmed_email values right now. At the time there was one for testing reasons, it was encrypted as expected.

Is it a requirement for there to be actual values at all for the rotation to work?

Edit: tested with an unconfirmed_email value. Still nothing.

[ankane]

Can you paste the stack trace for the error?

Also, I'd confirm you can still decrypt after doing step 5 (run User.last(50).map(&:email) in a fresh console). If you're seeing an error there, the old_master_key likely isn't the key that was used to encrypt.

[herunan]

I'm getting some odd behaviour where the first instance of User.first.email in a fresh new console results in successful decryption but a second attempt will not. No attempts of Lockbox.rotate(User, attributes: [:email, :unconfirmed_email]) worked. I restarted my machine just in case I was still somehow connected to the database and the results were the same.

irb(main):001:0> User.first.email
  User Load (0.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
=> "user@email.com"
irb(main):002:0> 
irb(main):003:0> User.first.email
  User Load (0.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
Traceback (most recent call last):
        1: from (irb):2:in `<main>'
Lockbox::DecryptionError (Decryption failed)

What was the master_key and then was the old_master_key was the first and only key I generated until the new one I wanted to rotate to.

This is the full trace:

irb(main):003:0> Lockbox.rotate(User, attributes: [:email, :unconfirmed_email])
  User Load (0.4ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1000]]
Traceback (most recent call last):
        2: from (irb):2:in `<main>'
        1: from (irb):3:in `rescue in <main>'
Lockbox::DecryptionError (Decryption failed)

I recreated the local database and created a new user account and a newly-generated set of keys. Then attempted to rotate following the steps above. Same results.

[herunan]

Okay, I found the issue. It seems that the previous key is accepted for the first decryption operation every time you start a Rails console session. As soon as you run a second operation, it won't accept the previous key. I connected the dots when I was able to rotate once I singled out the email with: Lockbox.rotate(User, attributes: [:email]) and then I wasn't able to rotate the unconfirmed email until I restarted the console. So rotating both fields separately worked with a restart in between. This also explains the above issue where I wasn't able to decrypt an email a second time within the same session. Is this a bug or a feature?

[ankane]

It seems like the issue is User.first.email decrypts the first time, but fails the second (rather than an issue specific to rotation). However, I'm not sure how to reproduce that behavior.

I'd try forking and adding some debugging around here to see how the options change between the first and second time.

Also, to get the full stack trace in the Rails console, you can do:

begin; User.last.email; rescue => e; puts e.backtrace; end

[herunan]

I've been using the same docs on a brand new Rails app and I'm facing the same issue on the second decryption per session.

These are my migrations:

class CreateUsers < ActiveRecord::Migration[6.0]
  def change
    create_table :users do |t|
      t.string :email

      t.timestamps
    end
  end
end

class AddEmailCiphertextToUsers < ActiveRecord::Migration[6.0]
  def change
    # encrypted data
    add_column :users, :email_ciphertext, :text

    # blind index
    add_column :users, :email_bidx, :string
    add_index :users, :email_bidx, unique: true

    # drop original here unless we have existing users
    remove_column :users, :email
  end
end

My model and initializer for the rotation setup after creating a user with email (master keys are throwaways):

class User < ApplicationRecord
  encrypts :email, previous_versions: [{master_key: '17f28762fe4f8d8a81f3ff739c7a6dc8e9aa2b871994fef1082e53f037f559f8'}]
  blind_index :email
end

Lockbox.master_key = '30fe1b6e1746ce2d84c3e6c3a8925954fccb3ed4c151afaa0ab6ab9478095c56'

# Old master key
# Lockbox.master_key = '17f28762fe4f8d8a81f3ff739c7a6dc8e9aa2b871994fef1082e53f037f559f8'

Full stack trace after decrypting a second time:

irb(main):001:0> begin; User.last.email; rescue => e; puts e.backtrace; end
  User Load (0.4ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT $1  [["LIMIT", 1]]
=> "user@email.com"
irb(main):002:0> begin; User.last.email; rescue => e; puts e.backtrace; end
  User Load (0.3ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT $1  [["LIMIT", 1]]
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/encryptor.rb:42:in `rescue in block in decrypt'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/encryptor.rb:33:in `block in decrypt'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/encryptor.rb:32:in `each'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/encryptor.rb:32:in `each_with_index'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/encryptor.rb:32:in `decrypt'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/model.rb:407:in `block (3 levels) in encrypts'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/lockbox-0.4.9/lib/lockbox/model.rb:328:in `block (3 levels) in encrypts'
(irb):2:in `irb_binding'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/workspace.rb:114:in `eval'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/workspace.rb:114:in `evaluate'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/context.rb:439:in `evaluate'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:540:in `block (2 levels) in eval_input'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:695:in `signal_status'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:537:in `block in eval_input'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/ruby-lex.rb:150:in `block (2 levels) in each_top_level_statement'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/ruby-lex.rb:135:in `loop'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/ruby-lex.rb:135:in `block in each_top_level_statement'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/ruby-lex.rb:134:in `catch'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb/ruby-lex.rb:134:in `each_top_level_statement'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:536:in `eval_input'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:471:in `block in run'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:470:in `catch'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:470:in `run'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/irb.rb:399:in `start'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/commands/console/console_command.rb:70:in `start'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/commands/console/console_command.rb:19:in `start'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/commands/console/console_command.rb:102:in `perform'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/thor-1.0.1/lib/thor/command.rb:27:in `run'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/thor-1.0.1/lib/thor/invocation.rb:127:in `invoke_command'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/thor-1.0.1/lib/thor.rb:392:in `dispatch'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/command/base.rb:69:in `perform'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/command.rb:46:in `invoke'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.4/lib/rails/commands.rb:18:in `<main>'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/zeitwerk-2.4.1/lib/zeitwerk/kernel.rb:33:in `require'
/Users/herunan/code/herunan/MyNewApp/bin/rails:9:in `<main>'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:72:in `require'
/Users/herunan/.rbenv/versions/2.7.1/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:72:in `require'
-e:1:in `<main>'
=> nil

[ankane]

From the stack trace, it looks like you're on Lockbox 0.4.9. Try upgrading to the latest version (0.6.2).

[herunan]

🤦‍♂️