Shovel URIs can be logged in crash.log by the runtime

[inikulshin]

RabbitMQ 3.8.9, Erlang 22.1, Windows 10

1. I added dummy shovel, using non-existing credentials (x:x, y:y):

http://localhost:15672/api/parameters/shovel

[{"value":{"ack-mode":"on-confirm","dest-add-forward-headers":false,"dest-protocol":"amqp091","dest-queue":"y","dest-uri":"amqp://y:y@localhost:5672","src-delete-after":"never","src-protocol":"amqp091","src-queue":"x","src-uri":"amqp://x:x@localhost:5672"},"vhost":"/","component":"shovel","name":"dummy"}]

2. %RABBITMQ_BASE%\log\log\crash.log:

2021-01-07 22:11:54 =SUPERVISOR REPORT====
     Supervisor: {<0.18232.0>,rabbit_shovel_dyn_worker_sup}
     Context:    child_terminated
     Reason:     shutdown
     Offender:   [{pid,<0.18560.0>},{name,{<<"/">>,<<"dummy">>}},{mfargs,{rabbit_shovel_worker,start_link,[dynamic,{<<"/">>,<<"dummy">>},[{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"amqp091">>},{<<"dest-queue">>,<<"y">>},{<<"dest-uri">>,<<"amqp://y:y@localhost:5672">>},{<<"src-delete-after">>,<<"never">>},{<<"src-protocol">>,<<"amqp091">>},{<<"src-queue">>,<<"x">>},{<<"src-uri">>,<<"amqp://x:x@localhost:5672">>}]]}},{restart_type,{permanent,5}},{shutdown,4294967295},{child_type,worker}]

As you can see, URIs in Offender contain unencrypted passwords despite it should not, by #2056

[inikulshin]

%RABBITMQ_BASE%\log\INIKULSHIN-PC.rabbit@localhost.log is good:

2021-01-07 22:11:54.487 [info] <0.18568.0> accepting AMQP connection <0.18568.0> (127.0.0.1:26492 -> 127.0.0.1:5672)
2021-01-07 22:11:54.493 [info] <0.18568.0> Connection <0.18568.0> (127.0.0.1:26492 -> 127.0.0.1:5672) has a client-provided name: Shovel dummy
2021-01-07 22:11:54.493 [error] <0.18568.0> Error on AMQP connection <0.18568.0> (127.0.0.1:26492 -> 127.0.0.1:5672, state: starting):
PLAIN login refused: user 'x' - invalid credentials
2021-01-07 22:11:54.493 [error] <0.18560.0> Shovel 'dummy' failed to connect (URI: amqp://localhost:5672): ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.
2021-01-07 22:11:54.493 [error] <0.18560.0> Shovel 'dummy' has no more URIs to try for connection
2021-01-07 22:11:54.493 [info] <0.18568.0> closing AMQP connection <0.18568.0> (127.0.0.1:26492 -> 127.0.0.1:5672 - Shovel dummy)
2021-01-07 22:11:54.493 [error] <0.18560.0> Shovel 'dummy' could not connect, caught exception error:failed_to_connect_using_provided_uris
2021-01-07 22:11:54.493 [error] <0.18560.0> Shovel 'dummy' could not connect to source
2021-01-07 22:11:54.494 [error] <0.18232.0> Supervisor {<0.18232.0>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"dummy">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"dummy">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at <0.18560.0> exit with reason shutdown in context child_terminated

[inikulshin]

Related sections of rabbtimq.config:

[
	{lager, [
		{error_logger_hwm, 1000},
		{crash_log_date, "$D0"},
		{crash_log_size, 268435456},
		{crash_log_count, 40}]},
	{rabbit, [
		{log, [
			{file, [
				{file, "INIKULSHIN-PC.rabbit@localhost.log"},
				{date, "$D0"},
				{size, 268435456},
				{count, 40},
				{formatter_config, [date," ",time," [",severity,"] ",{pid,[]}," ",message,"\r\n"]}]},

[michaelklishin]

This is a case our team is aware of and has considered.

#2056 addressed the problem for what is under our control: the Erlang client and Shovel worker, etc state when said state was successfully initialized. In your case the process never has a chance to actually initialize: it effectively immediately fails and that is logged by the runtime, which is why it shows up in the unhandled exception log, crash.log, not RabbitMQ's own log. Maybe this specific case can be addressed one way or another but in general, there always will be scenario where a complete process state can potentially be logged by Erlang/OTP too early for any of our own code to have a chance to encrypt parts of its state using credentials_obfuscation.

This is significantly less of a problem compared to what was covered in #2056: the cases where a process terminates for any reason after running for a period of time with valid credentials.

Arguably when your Shovels have no chance of starting at all, you do want to see what credentials were used easily in the exception log. If you think about it, logging credentials known to be invalid in a separate log file is not going to present a practical problem. So such specific cases is not a priority for our team. However, RabbitMQ is open source software so if you feel particularly strongly about this specific scenario, you are welcome to contribute a solution similarly to how we did it in #2056.

[inikulshin]

@michaelklishin I'm not familiar with your implementation, but I'm expecting RabbitMQ always uses URIs with encrypted passwords.

Not "decrypted URIs everywhere, encrypt password only before logging (and sometimes it's not under your control)",
but "encrypted URIs everywhere, decrypt password only before authenticating (always under your control)".

[inikulshin]

Another example:

[{"value":{"ack-mode":"on-confirm","dest-add-forward-headers":false,"dest-protocol":"amqp091","dest-queue":"x","dest-uri":"amqp://x:x@remotehost:5672","src-delete-after":"never","src-protocol":"amqp091","src-queue":"z","src-uri":"amqp://z:z@localhost:5672"},"vhost":"/","component":"shovel","name":"dummy"}]

2021-01-07 23:32:13.261 [info] <0.12414.0> Connection <0.12414.0> (127.0.0.1:29814 -> 127.0.0.1:5672) has a client-provided name: Shovel dummy
2021-01-07 23:32:13.262 [info] <0.12414.0> connection <0.12414.0> (127.0.0.1:29814 -> 127.0.0.1:5672 - Shovel dummy): user 'z' authenticated and granted access to vhost '/'
2021-01-07 23:32:16.529 [error] <0.12406.0> Shovel 'dummy' failed to connect (URI: amqp://remotehost:5672): unknown host (failed to resolve hostname)
2021-01-07 23:32:16.529 [error] <0.12406.0> Shovel 'dummy' has no more URIs to try for connection
2021-01-07 23:32:16.529 [error] <0.12406.0> Shovel 'dummy' could not connect to destination
2021-01-07 23:32:16.530 [error] <0.12055.0> Supervisor {<0.12055.0>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"dummy">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"dummy">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at <0.12406.0> exit with reason shutdown in context child_terminated
2021-01-07 23:32:16.530 [info] <0.12414.0> closing AMQP connection <0.12414.0> (127.0.0.1:29814 -> 127.0.0.1:5672 - Shovel dummy, vhost: '/', user: 'z')

2021-01-07 23:32:16 =SUPERVISOR REPORT====
Supervisor: {<0.12055.0>,rabbit_shovel_dyn_worker_sup}
Context: child_terminated
Reason: shutdown
Offender: [{pid,<0.12406.0>},{name,{<<"/">>,<<"dummy">>}},{mfargs,{rabbit_shovel_worker,start_link,[dynamic,{<<"/">>,<<"dummy">>},[{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"amqp091">>},{<<"dest-queue">>,<<"x">>},{<<"dest-uri">>,<<"amqp://x:x@remotehost:5672">>},{<<"src-delete-after">>,<<"never">>},{<<"src-protocol">>,<<"amqp091">>},{<<"src-queue">>,<<"z">>},{<<"src-uri">>,<<"amqp://z:z@localhost:5672">>}]]}},{restart_type,{permanent,5}},{shutdown,4294967295},{child_type,worker}]

Here the error is not invalid credentials, but both passwords are exposed: of successfully authenticated local z and remote x, that didn't even tried to authenticate, because of unknown host error.

[inikulshin]

And no, I never, never, never want to expose passwords in any logs, even on invalid credentials error. If it happened because of typo, the exposed password is a huge hint for brute force attack.

More than that, I think even http://localhost:15672/api/parameters/shovel must return URIs with encrypted passwords.

[michaelklishin]

As of #2056, the client used by Shovel and Federation encrypts credentials on init and decrypts them when they have to be used. If for any reason an exception is logged before the process had a chance to encrypt them, there is nothing that can be done to prevent the runtime from logging what's in the process state as part of an exception.

When initial connection fails repeatedly, arguably you do want to see the exact process state. I don't have much to add: the automatic state logging is a runtime feature. RabbitMQ itself never logs credentials. #2056 has shipped with RabbitMQ 3.8 and the issue hasn't been brought up more than a couple of times since then (in over a year). To me this means that the vast majority of cases where credentials could be logged were covered.

If there are cases that still need process state value encryption, you are welcome to contribute by following the examples in PRs referenced in #2056. RabbitMQ is open source software after all.

[michaelklishin]

@inikulshin there are no plans to make GET /api/parameters/shovel return encrypted values. The keys used as of #2056 are one-off, entirely transient and specific to the node. If we returned value with encrypted credentials, other nodes or even the same node after a restart would not be able to decrypt those values.

We appreciate your candid feedback on how you would like things to work but not everyone feels that way. Those who feel very strongly about a certain behavior are welcome to channel that energy into pull requests.

[inikulshin]

there is nothing that can be done to prevent the runtime from logging what's in the process state as part of an exception

You are right. But (imho) you can avoid [dumped] process state to contain plain passwords.

other nodes or even the same node after a restart would not be able to decrypt those values

It depends on encryption algorithm. And I think, no one should be able to decrypt, except the shovel itself for authentication only.

@michaelklishin I often disagree with you, but I really do appreciate the job you do (and your sophisticated sense of humor :)
So, enough with this issue, I'll say no more.
Thanks!

[michaelklishin]

Avoiding exceptions is what rabbitmq/rabbitmq-shovel#65 did, at least for the most common cases. We'll try to reproduce what you see. A quick comparison suggests that Federation currently encrypts more of its state than Shovel.

Whether other nodes or external tools can decrypt a certain value does not depend on the encryption algorithm. It depends on how the key pair was generated and is (or is not) distributed.

I now recall that as of credentials_obfuscation 2.0 there is a configurable value used for private key material, so all cluster nodes can decrypt a value encrypted by one of them. It's not the case when the origin and target nodes are in separate clusters because the seeding value is derived from the shared cluster-wide secret and those are supposed to be different between clusters.

The keys that are used to encrypt process state values are not meant to be shared with external tools, so if we did export any data encrypted by said keys, no other tool would be able to decrypt them.

[danmarcab]

Sorry to comment in such an old issue, first of all thanks for the amazing libraries!

We are experiencing the issue of a crash leaking rabbit_shovel_worker state including passwords. I am new to the codebase and wanted to make sure I understand the issue.

#3476 made the credentials obfuscated for rabbit_shovel_workers. But if I understand the code correctly, this only applies to dynamically started shovels.

We are using statically defined ones, started through

rabbitmq-server/deps/rabbitmq_shovel/src/rabbit_shovel_sup.erl

Line 54 in a23a348

start => {rabbit_shovel_worker_sup, start_link, [ShovelName, ShovelConfig]},

and therefore not covered by the aforementioned fix.

Am I correct on the interpretation? Is this a legit use case? Would a PR be welcome?

[lukebakken]

Hi @danmarcab, thank you for using RabbitMQ and taking the time to report that issue. Please feel free to submit a PR to add obfuscation to static shovels. If you could also open a new issue with the details you provided, and link to it in your PR, that would be great. Thanks again.