Closed AndrewDryga closed 5 years ago
Are you using version 1.0.4 of bcrypt_elixir?
In the error message, is the first number in the second argument of hash_nif
always 0 (zero), or is it always different?
Versions:
bcrypt_elixir 1.0.4 1.0.4
comeonin 4.0.3 4.0.3
Here are some other failures:
** (ArgumentError) argument error
code: account = insert(:account) |> start_password_reset()
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('secure_password', [0, 50, 98, 36, 48, 52, 36, 50, 81, 115, 68, 106, 117, 101, 75, 83, 99, 86, 106, 85, 70, 112, 106, 119, 68, 118, 54, 98, 117])
(bcrypt_elixir) lib/bcrypt/base.ex:59: Bcrypt.Base.hash/3
** (ArgumentError) The salt is the wrong length
code: account = insert(:account) |> start_password_reset()
stacktrace:
(bcrypt_elixir) lib/bcrypt/base.ex:31: Bcrypt.Base.hash_password/2
Not always zero:
** (ArgumentError) argument error
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('email_token', [36, 50, 98, 36, 48, 52, 36, 0, 84, 99, 77, 112, 84, 122, 65, 76, 69, 101, 99, 115, 50, 78, 79, 99, 110, 105, 103, 102, 79])
(bcrypt_elixir) lib/bcrypt/base.ex:59: Bcrypt.Base.hash/3
And even
** (Postgrex.Error) ERROR 22021 (character_not_in_repertoire): invalid byte sequence for encoding "UTF8": 0x00
code: account = insert(:account)
which shows that zero byte somehow gets into the hashing result.
We have just started encountering the same issues, with the same error messages as above. Errors are intermittently occurring (sometimes our test suite succeeds, sometimes fails with these bcrypt related errors).
I don't believe it's v1.0.4 related, as we have been using v1.0.4 of bcrypt_elixir since it was released (on 12th September), without any issues.
@AndrewDryga What version of Erlang are you guys using? We have just upgraded to Erlang OTP-20.1.6 (no problems occurring with OTP-20.1.5), could that be the common factor?
It most successfully reproduces on circleci/elixir:latest
container (which is used by our CI):
Erlang/OTP 20 [erts-9.1.4] [source] [64-bit] [smp:32:32] [ds:32:32:10] [async-threads:10] [hipe] [kernel-poll:false]
I've just tried using the latest commit to master ( https://github.com/riverrun/bcrypt_elixir/commit/a38cb3854c688e0ef54c4ca2425a9acd96aa7546 ) and so far this seems to have fixed our issue (i.e. no test failures after 3 test builds in our Circle CI environment).
updated mix.exs
...
{:bcrypt_elixir, github: "riverrun/bcrypt_elixir", override: true}
...
Amazing work @riverrun, thanks for such a speedy response to this problem!
The latest commit to master just simplified the salt generation nif code, and it's possible that it fixed the problem. I'll push it to hex now.
I will keep this issue open, and we will see if the changes really have fixed the issue.
@riverrun FYI. During our investigation of the issue, we found that to generate random salt nif part is using uninitialized integer, which can be broken by certain C compilers: https://stackoverflow.com/questions/31739792/is-uninitialized-local-variable-the-fastest-random-number-generator
And here is CVE based on this kind of behaviour in cryptographic functions: http://kqueue.org/blog/2012/06/25/more-randomness-or-less/
The actual randomness comes from :crypto.strong_rand_bytes
. The gensalt_nif
just formats the salt.
Got it, thanks 👍
@riverrun I've just checked and it still reproduces with the latest elixir_bcrypt
version from hex.pm:
1) test add_member_by_email/2 succeeds with valid params (MyApp.Domain.Team.UseCaseTest)
test/my_app/team/use_case_test.exs:29
** (ArgumentError) argument error
code: owner = insert(:account)
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('secure_password', [0, 50, 98, 36, 48, 52, 36, 117, 100, 48, 75, 88, 80, 101, 98, 100, 47, 116, 110, 53, 103, 104, 81, 112, 51, 51, 68, 46, 79])
(bcrypt_elixir) lib/bcrypt/base.ex:59: Bcrypt.Base.hash/3
* Updating bcrypt_elixir (Hex package)
Checking package (https://repo.hex.pm/tarballs/bcrypt_elixir-1.0.5.tar)
Fetched package
Could you edit the deps/bcrypt_elixir/c_src/bcrypt_nif.c
file and in the bcrypt_initsalt
function add printf("%s\n", salt);
before and after the call to encode_base64
? Let's try to get more data.
It's hard to tell which exact output is responsible for failure, because it doesn't reproduce with --trace
flag:
$2b$04$
$2b$04$pE0/eFeF.o.TUTFgOMW0je
2) test successfully register user with precreated account (MyApp.User.UseCases.RegisterTest)
test/my_app/user/use_cases/register/register_test.exs:18
** (ArgumentError) The salt is the wrong length
code: params = changeset_attrs_for(:account, %{"email" => precreated_account.email})
stacktrace:
(bcrypt_elixir) lib/bcrypt/base.ex:31: Bcrypt.Base.hash_password/2
All other entries are looking the same:
$2b$04$h.Cqdl5JSonSaqH5ACO3p.
$2b$04$
$2b$04$hZ.RMb5bwpLUVyw21Wkpf.
$2b$04$
$2b$04$3iIGw8WvTwNdBblzK7ERve
.$2b$04$
$2b$04$yNtCOuOrsstgVQ.JA8QaQO
.$2b$04$
$2b$04$uZ2qJUDG3Od82kWZHJYUeu
$2b$04$
$2b$04$BglmURWCp5MZWwJH67ZhJO
$2b$04$
$2b$04$FhFqD4rPkHDrppJ3O0g7uu
$2b$04$
$2b$04$ImC95AAIbaj.Cbjjiabs2e
.$2b$04$
$2b$04$7T67EgX2rFT9JnVwiVRUt.
$2b$04$
$2b$04$cu/j4hKUUWWmqxxvCNCOWO
$2b$04$
$2b$04$Q3ikDFM56o2kQb.cS5i/ku
.$2b$04$
$2b$04$P3BiT0sXtfX1xFnfIx2n0u
.$2b$04$
$2b$04$N2kZgkcCMZMk9xqz9gW0..
$2b$04$
$2b$04$H17HeRpgzwLtEs2PY7dhwO
.$2b$04$
$2b$04$4C9Xx4WaweU7XKFS52O/6e
$2b$04$
$2b$04$mDSuqH1aSViz/9fHqzMlWO
.$2b$04$
$2b$04$gw56eyxLLiagSYLF2H97/u
$2b$04$
$2b$04$onnVNOnAY7JsaByNj0GfNe
$2b$04$
$2b$04$fxfW5nrPB4STziKyJVxTGu
$2b$04$
$2b$04$aSwHczqeeZCTdF606iZgJ.
$2b$04$
$2b$04$HKSrUYLxNzS.IYFhtK9t2u
Another one:
$2b$04$
$2b$04$x.lDineYeNdxE2j4ph40pe
$2b$04$
$2b$04$gBRHA2IuYtHa2WKtkVKzY.
$2b$04$
$2b$04$fUh6KEgc3/AWfJ4fTPErNe
$2b$04$
$2b$04$bRwpY4nfpceEhrIHohXKwe
$2b$04$
$2b$04$5tA9bwd/fNEFuKRELjSlxe
1) test for third-party applications responds with error on removed token (my_appApi.OptionalAuthenticationPlugTest)
test/my_app/plugs/optional_authentication_plug_test.exs:104
** (ArgumentError) argument error
code: api_key = insert(:api_key, account: account, revoked_at: DateTime.utc_now())
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('secure_password', [36, 50, 98, 36, 48, 52, 36, 0, 115, 52, 103, 77, 110, 102, 82, 50, 65, 83, 118, 82, 51, 99, 69, 118, 116, 88, 117, 117, 79])
(bcrypt_elixir) lib/bcrypt/base.ex:59: Bcrypt.Base.hash/3
(my_app_domain) test/support/factory.ex:18: my_app.Domain.Factory.account_factory/0
(ex_machina) lib/ex_machina.ex:168: ExMachina.build/3
(my_app_domain) test/support/factory.ex:59: my_app.Domain.Factory.api_key_factory/0
(ex_machina) lib/ex_machina.ex:168: ExMachina.build/3
(my_app_domain) test/support/factory.ex:2: my_app.Domain.Factory.insert/2
test/my_app/plugs/optional_authentication_plug_test.exs:106: (test)
$2b$04$
$2b$04$WNCa2MpBLl5obvnh6Qi2Lu
.......$2b$04$
$2b$04$vF4NgDaw8QkAXvUQzFSVZ.
$2b$04$
$2b$04$Z3oV1SkRBFodUHGJC5.4pe
.$2b$04$
$2b$04$rREXCpAxhTJbH0fWpLdm3e
....$2b$04$
$2b$04$EOIflGD3.Y/QzAUizahnRu
.$2b$04$
$2b$04$66Vja6OTzpUTUJugmyvuku
What OS are you using?
What versions of Erlang and Elixir are you using?
In lib/bcrypt.ex
, add |> IO.inspect
to the gen_salt
function - after line 53, just before the end.
Looks fine for me:
$2b$04$
$2b$04$h0bjZrYOOqKqZ33OyEvlN.
"$2b$04$h0bjZrYOOqKqZ33OyEvlN."
$2b$04$
$2b$04$wdGeJYA0UU4gIR6ltx18Pe
4) test delete/2 returns 401 for unauthenticated request (MyApp.StoredContractControllerTest)
test/my_app_api/controllers/contract/stored_contract_controller_test.exs:143
** (ArgumentError) The salt is the wrong length
code: account = insert(:account)
stacktrace:
(bcrypt_elixir) lib/bcrypt/base.ex:31: Bcrypt.Base.hash_password/2
(my_app_domain) test/support/factory.ex:18: MyApp.Domain.Factory.account_factory/0
(ex_machina) lib/ex_machina.ex:168: ExMachina.build/3
(my_app_domain) test/support/factory.ex:2: MyApp.Domain.Factory.insert/2
test/my_app_api/controllers/contract/stored_contract_controller_test.exs:144: (test)
The following output was logged:
10:34:45.773 request_id=18b802uqd8japifhec897t6jo1e1pcmt [info] Received POST /drafts
10:34:45.773 request_id=022tgphv26al17lbp9ft62r3f5vbd782 [info] Rendered "409.json" in 0.0ms
10:34:45.773 request_id=022tgphv26al17lbp9ft62r3f5vbd782 [info] Sent 409 response in 1.84ms
10:34:45.773 request_id=18b802uqd8japifhec897t6jo1e1pcmt [info] Processing with MyApp.DraftController.create/2 Pipelines: [:api]
10:34:45.773 request_id=18b802uqd8japifhec897t6jo1e1pcmt [info] Rendered "errors.json" in 0.0ms
10:34:45.773 request_id=18b802uqd8japifhec897t6jo1e1pcmt [info] Sent 400 response in 614µs
"$2b$04$wdGeJYA0UU4gIR6ltx18Pe"
..$2b$04$
$2b$04$IZbkrG5Q2X4v6xwP9ZcynO
"$2b$04$IZbkrG5Q2X4v6xwP9ZcynO"
Here are arguments I'm getting in IO.inspect {pwd, salt}
placed in Bcrypt.Base.hash_password/2
(the one that raises exception):
$2b$04$
$2b$04$v11mnf1NCfX9QrFR2fCoI.
"$2b$04$v11mnf1NCfX9QrFR2fCoI."
"$2b$04$"
{"secure_password", "$2b$04$"}
Looks like I'm getting only salt prefix without a random part.
Versions:
Erlang/OTP 20 [erts-9.1.4] [source] [64-bit] [smp:32:32] [ds:32:32:10] [async-threads:10] [hipe] [kernel-poll:false]
circleci@e4baa378cace:~/project$ uname -m
x86_64
circleci@e4baa378cace:~/project$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 8 (jessie)"
NAME="Debian GNU/Linux"
VERSION_ID="8"
VERSION="8 (jessie)"
ID=debian
...
Got it:
Before encode: $2b$04$
After encode: $2b$04$MQhiezXhvJoeFAPa4EgDv.
Before encode: $2b$04$
HERE: gen_salt return:: "$2b$04$"
After encode: $2b$04$dtvdLZheS622L.vL6JN1yu
Before encode: $2b$04$dtvdLZheS622L.vL6JN1yu
After encode: $2b$04$aynLgluprTbWPihloQgmcO
gen_salt return:: "$2b$04$FruW5YQSANaIBYBbJvHHAu"
HERE: {"secure_password", "$2b$04$"}
gen_salt return:: "$2b$04$dtvdLZheS622L.vL6JN1yu"
gen_salt return:: "$2b$04$aynLgluprTbWPihloQgmcO"
1) test initializes password reset (MyApp.ResetPasswordStartControllerTest)
test/my_app/controllers/user/reset_password_start_controller_test.exs:4
** (ArgumentError) The salt is the wrong length
code: account = insert(:account)
Sometimes gen_salft returns empty string:
Before encode: $2b$04$
After encode: $2b$04$MJ5Dqj0Rt6aMDVwBzpAtFu
gen_salt return:: ""
gen_salt return:: "$2b$04$MJ5Dqj0Rt6aMDVwBzpAtFu"
{"secure_password", ""}
Sometimes iolist:
Before encode: $2b$04$
After encode: $2b$04$c3rAYrNoF6uIhQbmke97lO
Before encode: $2b$04$
After encode: $2b$04$f7nTht6CW98sFQ..ewC1rO
gen_salt return:: "$2b$04$f7nTht6CW98sFQ..ewC1rO"
gen_salt return:: <<36, 50, 98, 36, 48, 52, 36, 0, 51, 114, 65, 89, 114, 78, 111, 70, 54, 117, 73,
104, 81, 98, 109, 107, 101, 57, 55, 108, 79>>
Before encode: $2b$04$
After encode: $2b$04$oGtcxl8oth2TWDRoQrQp2u
gen_salt return:: "$2b$04$oGtcxl8oth2TWDRoQrQp2u"
3) test index/2 it returns only user drafts (MyApp.DraftControllerTest)
test/contractbook_api/controllers/contract/draft_controller_test.exs:112
** (ArgumentError) argument error
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('secure_password', [36, 50, 98, 36, 48, 52, 36, 0, 51, 114, 65, 89, 114, 78, 111, 70, 54, 117, 73, 104, 81, 98, 109, 107, 101, 57, 55, 108, 79])
(bcrypt_elixir) lib/bcrypt/base.ex:60: Bcrypt.Base.hash/3
Let's try removing the current printf, IO.inspect calls and then replace the gen_salt function, in the lib/bcrypt.ex
file with the following:
def gen_salt(log_rounds \\ 12, legacy \\ false) do
:crypto.strong_rand_bytes(16)
|> IO.inspect
|> :binary.bin_to_list
|> Base.gensalt_nif(log_rounds, legacy and 97 || 98)
|> IO.inspect
|> :binary.list_to_bin
end
@riverrun
nif return: '$2b$04$bvxjwM.4iu524N3KFPS67.'
....generated bytes: <<37, 166, 124, 105, 108, 227, 117, 0, 164, 251, 69, 148, 81, 27, 34, 171>>
generated bytes: <<7, 182, 69, 81, 171, 10, 137, 117, 215, 178, 97, 77, 139, 23, 209, 204>>
nif return: []
generated bytes: <<147, 51, 244, 111, 98, 79, 169, 45, 97, 36, 69, 56, 0, 205, 93, 38>>
nif return: '$2b$04$HYX6YUxhbOAi8yUSSPqgou'
generated bytes: <<231, 153, 185, 146, 75, 234, 137, 14, 82, 59, 40, 113, 239, 62, 72, 187>>
nif return: '$2b$04$ixNyZ0HNoQzfHCS2.KzbHe'
nif return: '$2b$04$33k3iitogO3QMwfv5x3Gsu'
...
1) test successful token generation (MyApp.User.UseCases.ResetPasswordStart.PersistorTest)
test/my_app/user/use_cases/reset_password_start/persistor_test.exs:5
** (ArgumentError) The salt is the wrong length
code: account = insert(:account)
stacktrace:
(bcrypt_elixir) lib/bcrypt/base.ex:31: Bcrypt.Base.hash_password/2
If you switch to version 0.12, do you get the same errors?
Could you try changing O3 to O2 in the CFLAGS?
Any news?
@riverrun version 0.12 works fine.
With O2 it still doesnt work:
==> bcrypt_elixir
mkdir -p priv
cc -g -O2 -Wall -I/usr/local/lib/erlang/erts-9.1.5/include -Ic_src -fPIC -shared c_src/bcrypt_nif.c c_src/blowfish.c -o priv/bcrypt_nif.so
...
** (ArgumentError) argument error
code: account = insert(:precreated_account)
stacktrace:
(bcrypt_elixir) Bcrypt.Base.hash_nif('email_token', [0, 50, 98, 36, 48, 52, 36, 85, 103, 90, 50, 70, 83, 109, 84, 67, 122, 118, 68, 110, 86, 46, 66, 108, 84, 80, 46, 84, 117])
Try deleting the _build
directory and running the tests again.
Could you show me the full code for one of your tests? That might help.
@riverrun we are using ExMachina to generate fixtures, here is the factory that uses hashing and fails:
@password "secure_password"
def account_factory do
id = Ecto.UUID.generate()
%Account{
id: id,
email: sequence(:email, &"email-#{&1}@example.com"),
phone_number: sequence(:phone_number, &"+44 100200#{&1}"),
profile: build(:profile, account_id: id),
password: @password,
password_hash: Comeonin.Bcrypt.hashpwsalt(@password)
}
end
So, basically, we always hash a constant value but because of seeding nif it sometimes fails.
Deleting _build
after setting O2
in CFLAGS did not help.
@rickclare can you confirm that you don't have issues anymore?
@AndrewDryga Unfortunately we are still getting an occasionally failing test-suite with the (ArgumentError) argument error
and (ArgumentError) The salt is the wrong length
errors.
Probably doesn't help with diagnostics, but the failures aren't as frequent any more (e.g. our test suite is only failing "1 in 10" times, instead of "1 in 3" times). Hence why I initially thought that the problem had been fixed with the recent commit to master.
@AndrewDryga are you getting any problems in Dev, or "Local test" environments, or is it just CI environment? For us, we've only noticed issues in our CI environment (which is running an Ubuntu 16.04 docker image). Dev and "local test" are running macOS 10.13.1
Here is our Docker image, if that's any use for comparison/diagnostics: https://hub.docker.com/r/myfuturenow/myfuturenow_phoenix_base
@rickclare It's only reproduced on CI environment, with runs in Docker container (circleci/elixir:latest
). And only when tests are running in async, I wasn't able to reproduce them with mix test --trace
.
For the record, I'm on Ubuntu 17.10 - with Erlang 20.1 and Elixir 1.6-dev.
I can't reproduce any of the errors you are getting, which makes it difficult for me to help you. I'll continue to look into it, and let me know if you have any news for me.
@AndrewDryga I can concur that we only get the problem when we run our tests async
I have added a note about using async: true
with version 1.0 to the README.
I have the same issue with 1.0.6
but only on my CI environment (CircleCI) on the image bitwalker/alpine-elixir:1.6.4
.
Could you let me know what output there is? And is it only when running async: true
?
error: argument error
(bcrypt_elixir) Bcrypt.Base.hash_nif('Come0n1n', [0, 50, 98, 36, 48, 52, 36, 68, 107, 78, 105, 49, 104, 118, 110, 104, 107, 89, 56, 78, 69, 78, 48, 83, 110, 75, 99, 112, 79])
(bcrypt_elixir) lib/bcrypt/base.ex:63: Bcrypt.Base.hash/3
(blend) test/support/factory.ex:13: Blend.Factory.user_factory/0
(ex_machina) lib/ex_machina.ex:170: ExMachina.build/3
Yeah only with async: true
and it's also happening from time to time.
Ok - thanks for the info. I'll have another look at it and get back to you soon.
@riverrun if you want we can make a screen share call, I can boot one of the CircleCI instances with SSH mode on and you would be able to run any commands to debug it.
Also, It should be fairly easy to create a PR which builds this repo in Elixir and test it there. If you don't have enough time for that - tell me and I'll make one.
@AndrewDryga thanks for the offer. Let me think about it, and I'll get back to you. Unfortunately, I don't have much time at the moment, but I would like to get to the bottom of this.
I am running into this issue as well on OSX as well as on an alpine container running the most recent version of elixir and erlang. The issue is intermittent as others have described.
I think it may be useful to print the actual salt that is causing the error message as it would give us more info into why there is a failure w/o leaking anything useful.
Change
def hash_password(_, _) do
raise ArgumentError, "The salt is the wrong length"
end
To
def hash_password(_, salt) do
raise ArgumentError, "#{salt} must be 29 bytes long"
end
By seeing the actual salt generated we will likely be able to better diagnose the problem.
@tomciopp thanks for reporting this. Do you ever have this issue locally?
I've just released 1.0.7 with the changes you suggested.
I have opened a new branch, called fix_salt_bug
, and in it I've some minor changes to the C code. If you could try these changes, that would be great.
Other changes you could try are deleting the explicit type cast to uint8_t on lines 278 and 319.
Let me know how you get on.
@riverrun Yes, I've had this issue locally as well as on CI. I will update to the newest version and the next time I see the error I will report back. I would also suggest that you move the following comment to the top of the NIF as I thought that it was entirely copy/pasted from OpenBSD.
* This version, to be used with Erlang / Elixir, has been implemented
* by David Whitlock and Jason M Barnes.
*
Now I know to be a bit more suspicious of the C code ;)
@riverrun, me and @marinho10 just updated bcrypt_elixir
to 1.0.7
in one of our projects running on circleCI, removed async: false
and the tests ran just fine.
thanks for the fix!
@tomciopp if you could also try the fix_salt_bug
branch, that would be really helpful.
About the C code, it is as close as it can be to the openBSD version. The only differences are due to connecting it to Erlang, and there are a couple of places where I had to make explicit casts because the implicit casts in the openBSD version were resulting in compiler warnings.
@riverrun is there a way to specify the salt to be used?
We are randomly getting the The salt xyz must be 29 bytes long
error when using the Bcrypt.Base.hash_password/2
function
** (ArgumentError) The salt $2b$12$ must be 29 bytes long
(bcrypt_elixir) lib/bcrypt/base.ex:35: Bcrypt.Base.hash_password/2
When are you getting these errors and how often? Is it only when running continuous integration and running async, or do you get them locally as well?
You can specify your own salt in the Bcrypt.Base.hash_password
function. The second argument is the salt.
Do you normally use Bcrypt.hash_pwd_salt
or Bcrypt.Base.hash_password
?
Hello there,
We are experiencing flaky test behaviour while using latest bcrypt_elixir:
Here is how Bcrypt used here: