blueriver/MuraCMS — pull request #1245 by jamiejackson (2014-01-28 00:11:35+00:00)
Title: Improving Password Hashing Performance Under Load

# Problem Symptoms:

I found that during times of heavy concurrent new password creation (which is part of both password resetting and new user registration), my application would buckle. During those times, requests would stack up at this point in their stack traces:

```
java.io.FileInputStream.readBytes(FileInputStream.java:???)[Native Method]
java.io.FileInputStream.read(FileInputStream.java:220)
sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedBytes(SeedGenerator.java:493)
sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:117)
sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:106)
java.security.SecureRandom.generateSeed(SecureRandom.java:495)
com.rsa.jsafe.provider.c7.engineGenerateSeed(null:???)
java.security.SecureRandom.generateSeed(SecureRandom.java:495)
java.security.SecureRandom.getSeed(SecureRandom.java:482)
com.rsa.jsafe.crypto.au.g(null:???)
com.rsa.jsafe.crypto.au.a(null:???)
com.rsa.jsafe.provider.JSA_FIPS186PRNGXChangeNoticeGeneral.engineNextBytes(null:???)
java.security.SecureRandom.nextBytes(SecureRandom.java:433)
BCrypt.gensalt(BCrypt.java:708)
BCrypt.gensalt(BCrypt.java:727)
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:???)[Native Method]
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
coldfusion.runtime.java.JavaProxy.invoke(JavaProxy.java:97)
coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2360)
cfutility2ecfc1810486443$funcTOBCRYPTHASH.runFunction(/home/onecpd/public_html/model/main/com/icfi/mura/utility.cfc:27)
```

I believe this is due to many concurrent threads trying to get entropy from the EGD (this is Linux, so /dev/urandom or /dev/random), and the EGD being unable to keep up with demand.

It is inadvisable and unnecessary to re-seed every time a password needs to be hashed: http://www.cigital.com/justice-league-blog/2009/08/14/proper-use-of-javas-securerandom/

# Modification

Reusing generated salt for a configurable length of time via `settings.ini.cfm`'s new `BCryptReseedFrequency` configuration variable. (Time to re-seed in minutes; defaults to 60m.)

If anyone wanted the old behavior (which I would advise against), they could set this value to 0.

# Test

```coldfusion

utility = application.utility;

for (i=1; i <= 10; i++) {
utility.toBCryptHash("hi");
}

```

## Test Results Before Modification

Note:

* Increasing execution times of "Generate Salt"):
* Entropy depletion, which I believe led to blocking due to genSalt() waiting for entropy to accumulate in the EGD:

```
"Information","jrpp-24","01/27/14","12:41:22","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 168b of entropy."
"Information","jrpp-24","01/27/14","12:41:22","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 8b of entropy. | 21 ms"
"Information","jrpp-24","01/27/14","12:41:22","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 8b"
"Information","jrpp-24","01/27/14","12:41:22","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 9b | execution time: 314 ms | stdout: [$2a$10$MKWtUt9D0Xm/EqdpAVEow.zlzIJNDSp2ta6uHGfLo.z.j/IBVwff2 ] | stderr: []"
"Information","jrpp-25","01/27/14","12:42:26","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 188b of entropy."
"Information","jrpp-25","01/27/14","12:42:26","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 28b of entropy. | 18 ms"
"Information","jrpp-25","01/27/14","12:42:26","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 28b"
"Information","jrpp-25","01/27/14","12:42:26","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 42b | execution time: 274 ms | stdout: [$2a$10$0QCi.Bh/qalMqlu/56olnOgl6AsbOZpAeX8eVO2IeAyIpBn8MTJbu ] | stderr: []"
"Information","jrpp-22","01/27/14","12:42:51","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 151b of entropy."
"Information","jrpp-22","01/27/14","12:42:51","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 7b of entropy. | 16 ms"
"Information","jrpp-22","01/27/14","12:42:51","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 7b"
"Information","jrpp-22","01/27/14","12:42:51","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 7b | execution time: 291 ms | stdout: [$2a$10$fonuuIrZCG4DUSzSxnjFh.TmLSExpgyjuXUNKk9QqSRA4jFt9nZOy ] | stderr: []"
"Information","jrpp-30","01/27/14","12:56:58","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 140b of entropy."
"Information","jrpp-30","01/27/14","12:56:58","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 4b of entropy. | 12 ms"
"Information","jrpp-30","01/27/14","12:56:58","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 4b"
"Information","jrpp-30","01/27/14","12:56:58","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 33b | execution time: 323 ms | stdout: [$2a$10$qDt6W3ZSAJHlfc.iAE5F..qrTKn/BWVF/7gIk/ac3GanBQz68pasm ] | stderr: []"
"Information","jrpp-30","01/27/14","12:56:58","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 33b of entropy."
"Information","jrpp-30","01/27/14","12:57:01","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 0b of entropy. | 2194 ms"
"Information","jrpp-30","01/27/14","12:57:01","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 1b"
"Information","jrpp-30","01/27/14","12:57:01","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 30b | execution time: 297 ms | stdout: [$2a$10$QuGtVLtL2gvpan/lQqKCV.97LrTg37WqNXimR8ogYqKFj221zlGp. ] | stderr: []"
"Information","jrpp-30","01/27/14","12:57:01","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 30b of entropy."
"Information","jrpp-30","01/27/14","12:57:06","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 1b of entropy. | 5359 ms"
"Information","jrpp-30","01/27/14","12:57:06","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 1b"
"Information","jrpp-30","01/27/14","12:57:07","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 1b | execution time: 328 ms | stdout: [$2a$10$Ivfogn//40qZSw0Bw21TfOSpc78hXdg2xmPDGdztV93M23wKSvH5C ] | stderr: []"
"Information","jrpp-30","01/27/14","12:57:07","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 1b of entropy."
"Information","jrpp-30","01/27/14","12:57:28","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 2b of entropy. | 21206 ms"
"Information","jrpp-30","01/27/14","12:57:28","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 2b"
"Information","jrpp-30","01/27/14","12:57:28","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 11b | execution time: 303 ms | stdout: [$2a$10$nzhJUSXoJtKwwJHZ5B6YI.dT7qyZjXLC0W6WTswCtKkHatN23Y12e ] | stderr: []"
"Information","jrpp-30","01/27/14","12:57:28","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 11b of entropy."
"Information","jrpp-30","01/27/14","12:57:42","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 8b of entropy. | 13855 ms"
"Information","jrpp-30","01/27/14","12:57:42","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 8b"
"Information","jrpp-30","01/27/14","12:57:42","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 8b | execution time: 286 ms | stdout: [$2a$10$0RBiamuuN8PSFcvpSJtc6uuirp.ImHAQaTVlP37HGWZXceeWrm86y ] | stderr: []"
"Information","jrpp-30","01/27/14","12:57:42","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 8b of entropy."
"Information","jrpp-30","01/27/14","12:58:05","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 0b of entropy. | 22778 ms"
"Information","jrpp-30","01/27/14","12:58:05","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 0b"
"Information","jrpp-30","01/27/14","12:58:05","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 0b | execution time: 295 ms | stdout: [$2a$10$zXc6.jW0eZw4ZO5/QR2cRexp8nawND.s1vWKQ6.NgWBT0tO5IBIF2 ] | stderr: []"
"Information","jrpp-30","01/27/14","12:58:05","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 0b of entropy."
"Information","jrpp-30","01/27/14","12:58:20","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 1b of entropy. | 14840 ms"
"Information","jrpp-30","01/27/14","12:58:20","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 1b"
"Information","jrpp-30","01/27/14","12:58:20","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 7b | execution time: 303 ms | stdout: [$2a$10$YfzGzcdYfyz7m6sxgE8lL.Wc8z/YwAYiUZKpFQoXeVNgrvhUjk38y ] | stderr: []"
"Information","jrpp-30","01/27/14","12:58:20","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 7b of entropy."
"Information","jrpp-30","01/27/14","12:58:41","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 0b of entropy. | 20365 ms"
"Information","jrpp-30","01/27/14","12:58:41","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 0b"
"Information","jrpp-30","01/27/14","12:58:41","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 31b | execution time: 303 ms | stdout: [$2a$10$mCqYniMaX3/5sEV9UfVmCeVreJudYJhGQuIgDam/iEhxe.CcawkVK ] | stderr: []"
"Information","jrpp-30","01/27/14","12:58:41","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 31b of entropy."
"Information","jrpp-30","01/27/14","12:58:43","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 0b of entropy. | 1952 ms"
"Information","jrpp-30","01/27/14","12:58:43","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 2b"
"Information","jrpp-30","01/27/14","12:58:43","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 21b | execution time: 303 ms | stdout: [$2a$10$zv5rIbMOOuxu7wqgWqZs5ubF6n7heCXBJAZFRvtFWB/6nhalBZnue ] | stderr: []"
"Information","jrpp-30","01/27/14","12:58:43","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 21b of entropy."
"Information","jrpp-30","01/27/14","12:59:04","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 0b of entropy. | 20741 ms"
"Information","jrpp-30","01/27/14","12:59:04","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call started with an entropy size of: 1b"
"Information","jrpp-30","01/27/14","12:59:04","MURAF89995153013987BB24A15CCA2C492EA","BCryptHashPw call ended with an entropy size of: 2b | execution time: 324 ms | stdout: [$2a$10$yZ/MIZigEGXyWDMK/D2RUuUKmyO9vZQm30VM2WdwQpuqRtI.p/oYy ] | stderr: []"
```

## Test Results After Modification

Note:

* Reuse of the salt
* Much better performance

```
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 132b"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Starting with 132b of entropy."
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","Generate Salt Ended with 4b of entropy."
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 14b | 209 ms"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 14b"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 19b | 179 ms"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 19b"
"Information","jrpp-39","01/27/14","13:01:28","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 25b | 175 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 25b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 28b | 152 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 28b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 40b | 144 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 40b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 42b | 134 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 42b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 52b | 162 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 52b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 58b | 138 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 58b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 69b | 148 ms"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash starting with an entropy size of: 69b"
"Information","jrpp-39","01/27/14","13:01:29","MURAF89995153013987BB24A15CCA2C492EA","minutesSinceSaltCreated = 0 (re-seed set to 1)"
"Information","jrpp-39","01/27/14","13:01:30","MURAF89995153013987BB24A15CCA2C492EA","toBCryptHash ending with an entropy size of: 77b | 153 ms"
```