Encryption and decryption is not thread safe

[DimitriosLisenko]

We are observing the following sporadic errors when using this gem:

• ArgumentError with must specify an iv
• OpenSSL::Cipher::CipherError

I can replicate this with multiple threads - when one thread is setting the encrypted value to an empty string, and another is setting it to a non-empty string, it's possible for the internal state of @encrypted_attributes to be changed such that the iv is not loaded when it is actually required.

Here is a reproduction script for the ArgumentError, using the example in the current README (though I have also obtained the OpenSSL::Cipher::CipherError with it when I was saving objects to the database):

require "securerandom"
class TestCase
	extend AttrEncrypted
	attr_accessor :name
	attr_encrypted :ssn, key: SecureRandom.hex(16)
end

def replicate_issue(x, times)
	loop do
		threads = []
		times.times do
			threads << Thread.new do
				x.ssn = ""
			end
			threads << Thread.new do
				x.ssn = "hello"
			end
		end
		threads.each(&:join)
	end
end

x = TestCase.new
replicate_issue(x, 10)

[engwan]

Looks like this is fixed in master: d4ca0e2

Took us a while to figure this out too. This seems pretty bad.

[formigarafa]

I have just run the code provided above against master and it as you can see it is still an issue.

$> bundle show attr_encrypted
/Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c
$> rails c
Running via Spring preloader in process 86781
Loading development environment (Rails 5.2.4.1)

Frame number: 0/29
irb(main):001:0> require "securerandom"
=> false

irb(main):002:0> class TestCase
irb(main):003:1>   extend AttrEncrypted
irb(main):004:1>   attr_accessor :name
irb(main):005:1>   attr_encrypted :ssn, key: SecureRandom.hex(16)
irb(main):006:1>   end
=> [:ssn]

irb(main):008:0> def replicate_issue(x, times)
irb(main):009:1>   loop do
irb(main):010:2*       threads = []
irb(main):011:2>     times.times do
irb(main):012:3*         threads << Thread.new do
irb(main):013:4*           x.ssn = ""
irb(main):014:4>         end
irb(main):015:3>       threads << Thread.new do
irb(main):016:4*           x.ssn = "hello"
irb(main):017:4>         end
irb(main):018:3>       end
irb(main):019:2>     threads.each(&:join)
irb(main):020:2>     end
irb(main):021:1>   end
=> :replicate_issue

irb(main):023:0> x = TestCase.new
=> #<TestCase:0x00007fcfbda44450>

irb(main):024:0> replicate_issue(x, 10)
#<Thread:0x00007fcfbe785df8@(irb):15 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
       5: from (irb):16:in `block (3 levels) in replicate_issue'
       4: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:167:in `block (2 levels) in attr_encrypted'
       3: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:352:in `encrypt'
       2: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:268:in `encrypt'
       1: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/encryptor-3.0.0/lib/encryptor.rb:36:in `encrypt'
/Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/encryptor-3.0.0/lib/encryptor.rb:61:in `crypt': must specify an iv (ArgumentError)
Traceback (most recent call last):
       6: from (irb):16:in `block (3 levels) in replicate_issue'
       5: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:167:in `block (2 levels) in attr_encrypted'
       4: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:352:in `encrypt'
       3: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/bundler/gems/attr_encrypted-11df93aef14c/lib/attr_encrypted.rb:268:in `encrypt'
       2: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/encryptor-3.0.0/lib/encryptor.rb:36:in `encrypt'
       1: from /Users/me/.asdf/installs/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/encryptor-3.0.0/lib/encryptor.rb:61:in `crypt'
ArgumentError (must specify an iv)

[formigarafa]

It seems #345 works well.
At least it does not fail for the example code above.

[engwan]

It seems #345 works well.
At least it does not fail for the example code above.

I think d4ca0e2 is the better fix and it's already merged into master 2 years ago.

The problem here is that a new version wasn't released from master.

[formigarafa]

@engwan , I tested against master, it fails.
Just copy the lines @DimitriosLisenko suggest above and run against master and you will see that the whatever was fixed on d4ca0e2 does not fix the scenario above.

I guess the key here is each of two threads setting the value to a blank and a non-blank value. It eventually will raise must specify an iv. I believe this happens because the iv is not set when setting to blank value while the other thread need one.

[formigarafa]

@engwan , Managed to write a spec (#377) that reproduces the problem. Please, have a look.

[engwan]

I see the problem now. It happens when it's the same instance being modified by multiple threads.

d4ca0e2 fixed the problem where different instances were modified in separate threads because the attributes were stored in a class variable. Now it's stored per instance.

Yes this is still a bug, but I think it's less severe than the previous one. I think it's not so common to modify the same instance in multiple threads.

[formigarafa]

@engwan,
I was a bit unsure to try master in production before our talk because I could still reproduce the failure with the code above.
But, as you told, under normal conditions this example does not represent the reality because it is unusual to be sharing instances across threads.
So I am giving master branch go.
I used to have hundreds of these failures a day with version 3.1.0 and it has been 13 hours more than a day without a single occurrence.

[jpcamara]

See my response on #344 (comment) - this issue is resolved if you point to the commits on master

Seems there is something that still causes this.

It takes alot of throughput to generate the error (attempts to reproduce on my local machine using threads pumping decrypts through have been unsuccessful).

In my case, every non-threaded environment (accessing from a console, running in a standalone daemon, multi process servers) never hits an issue. But when run in a threaded environment (sidekiq) with high throughput, I get the issue hundreds of times a day.

I have three models.

• 2 models are involved in 10s to low 100s of thousands of jobs a day. They randomly get OpenSSL::Cipher::CipherError throughout the day (low hundreds of times).
• 1 model is involved in 100s of thousands to low millions of jobs per day. It randomly gets must specify an iv (also low hundreds of times per day).
• Interestingly, they consistently get the same error - the 2 models always get CipherError when they fail and the third model always gets must specify an iv when it fails.

The code is very vanilla model lookups. The job starts with a find, and as part of the job it grabs the encrypted field. There's no shared state between jobs, aside from whatever Rails shares in caches and pools across threads. The encrypted columns were previously unencrypted, and the moment we moved to use encryption they started getting these errors every day (for a time we had the old column still on the table, but we dropped them and that didn't help either).

The only thing that has helped was moving these models/jobs to a special sidekiq process with single thread concurrency (so effectively making them non-threaded environments).

Just noting this here in case anyone else experiences it.

[jpcamara]

Looks like this is fixed in master: d4ca0e2

Took us a while to figure this out too. This seems pretty bad.

In response to my comment above, the fix on master does fix my issue. What I didn't realize was a new version of this gem has not been released since Feb 2018, and the fix was merged into master on Jul 2018 🤯.

The main concept of this particular issue (actually updating the same instance between threads) is not really a realistic case imo (but was very helpful for debugging!).