Using use_json logging leaks credentials

[Mohammed Naser]

The following was observed in the OpenStack Ansible CI when use_json was used in oslo.log, it looks like it passes out all the items serialized which can cause credentials to be leaked:

http://logs.openstack.org/61/591961/2/check/openstack-ansible-functional-ubuntu-xenial/f1781ce/logs/host/cinder-volume.service.journal.log.txt.gz#_Aug_15_11_10_32

[in case it gets deleted]

Aug 15 11:10:33 ubuntu-xenial-ovh-gra1-0001333882 cinder-volume[23478]: {"thread_name": "MainThread", "extra": {"project": "unknown", "version": "unknown"}, "process": 23478, "relative_created": 2235828.4900188446, "module": "impl_rabbit", "message": "[31818cce-51f4-402c-ad62-f3674460d470] Reconnected to AMQP server on 10.1.1.101:5672 via [amqp] client with port 54050.", "hostname": "ubuntu-xenial-ovh-gra1-0001333882", "filename": "impl_rabbit.py", "levelno": 20, "lineno": 778, "asctime": "2018-08-15 11:10:33", "msg": "[%(connection_id)s] Reconnected to AMQP server on %(hostname)s:%(port)s via [%(transport)s] client with port %(client_port)s.", "error_summary": "", "args": {"hostname": "10.1.1.101", "userid": "cinder", "password": "secrete", "virtual_host": "/cinder", "port": 5672, "insist": false, "ssl": false, "transport": "amqp", "connect_timeout": 5, "transport_options": {"on_blocked": "<function _on_connection_blocked at 0x7fb2fc3282a8>", "on_unblocked": "<function _on_connection_unblocked at 0x7fb2fc328320>", "client_properties": {"connection_name": "cinder-volume:23478:31818cce-51f4-402c-ad62-f3674460d470", "capabilities": {"connection.blocked": true, "authentication_failure_close": true, "consumer_cancel_notify": true}}, "confirm_publish": true}, "login_method": "AMQPLAIN", "uri_prefix": null, "heartbeat": 60.0, "failover_strategy": "round-robin", "alternates": [], "client_port": 54050, "connection_id": "31818cce-51f4-402c-ad62-f3674460d470"}, "process_name": "MainProcess", "name": "oslo.messaging._drivers.impl_rabbit", "thread": 140406697963024, "created": 1534331433.086563, "traceback": null, "msecs": 86.5631103515625, "funcname": "on_reconnection", "pathname": "/openstack/venvs/cinder-testing/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py", "context": {}, "levelname": "INFO"}

Aug 15 11:10:33 ubuntu-xenial-ovh-gra1-0001333882 cinder-volume[23478]: {"thread_name": "MainThread", "extra": {"project": "unknown", "version": "unknown"}, "process": 23478, "relative_created": 2235829.628944397, "module": "impl_rabbit", "message": "[b956eec0-15bb-4070-8a23-fd0f3c5e5a8e] Reconnected to AMQP server on 10.1.1.101:5672 via [amqp] client with port 54048.", "hostname": "ubuntu-xenial-ovh-gra1-0001333882", "filename": "impl_rabbit.py", "levelno": 20, "lineno": 778, "asctime": "2018-08-15 11:10:33", "msg": "[%(connection_id)s] Reconnected to AMQP server on %(hostname)s:%(port)s via [%(transport)s] client with port %(client_port)s.", "error_summary": "", "args": {"hostname": "10.1.1.101", "userid": "cinder", "password": "secrete", "virtual_host": "/cinder", "port": 5672, "insist": false, "ssl": false, "transport": "amqp", "connect_timeout": 5, "transport_options": {"on_blocked": "<function _on_connection_blocked at 0x7fb2fc3282a8>", "on_unblocked": "<function _on_connection_unblocked at 0x7fb2fc328320>", "client_properties": {"connection_name": "cinder-volume:23478:b956eec0-15bb-4070-8a23-fd0f3c5e5a8e", "capabilities": {"connection.blocked": true, "authentication_failure_close": true, "consumer_cancel_notify": true}}, "confirm_publish": true}, "login_method": "AMQPLAIN", "uri_prefix": null, "heartbeat": 60.0, "failover_strategy": "round-robin", "alternates": [], "client_port": 54048, "connection_id": "b956eec0-15bb-4070-8a23-fd0f3c5e5a8e"}, "process_name": "MainProcess", "name": "oslo.messaging._drivers.impl_rabbit", "thread": 140406697962544, "created": 1534331433.087702, "traceback": null, "msecs": 87.70203590393066, "funcname": "on_reconnection", "pathname": "/openstack/venvs/cinder-testing/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py", "context": {}, "levelname": "INFO"}

Aug 15 11:10:33 ubuntu-xenial-ovh-gra1-0001333882 cinder-volume[23478]: {"thread_name": "GreenThread-2", "extra": {"project": null, "version": "unknown"}, "process": 23478, "relative_created": 2235847.9709625244, "module": "impl_rabbit", "message": "[a2a29ff1-a431-4db5-9d05-f3ffb68d431d] AMQP server on 10.1.1.101:5672 is unreachable: [Errno 32] Broken pipe. Trying again in 1 seconds.", "hostname": "ubuntu-xenial-ovh-gra1-0001333882", "filename": "impl_rabbit.py", "levelno": 40, "lineno": 751, "asctime": "2018-08-15 11:10:33", "msg": "[%(connection_id)s] AMQP server on %(hostname)s:%(port)s is unreachable: %(err_str)s. Trying again in %(sleep_time)d seconds.", "error_summary": "error: [Errno 32] Broken pipe", "args": {"transport_options": {"on_blocked": "<function _on_connection_blocked at 0x7fb2fc3282a8>", "on_unblocked": "<function _on_connection_unblocked at 0x7fb2fc328320>", "client_properties": {"connection_name": "cinder-volume:23478:a2a29ff1-a431-4db5-9d05-f3ffb68d431d", "capabilities": {"connection.blocked": true, "authentication_failure_close": true, "consumer_cancel_notify": true}}, "confirm_publish": true}, "failover_strategy": "round-robin", "connection_id": "a2a29ff1-a431-4db5-9d05-f3ffb68d431d", "insist": false, "ssl": false, "client_port": null, "password": "secrete", "port": 5672, "transport": "amqp", "alternates": [], "err_str": "error(32, 'Broken pipe')", "login_method": "AMQPLAIN", "hostname": "10.1.1.101", "userid": "cinder", "connect_timeout": 5, "virtual_host": "/cinder", "heartbeat": 60.0, "uri_prefix": null, "sleep_time": 1.0}, "process_name": "MainProcess", "name": "oslo.messaging._drivers.impl_rabbit", "thread": 140406697962864, "created": 1534331433.106044, "traceback": null, "msecs": 106.04405403137207, "funcname": "on_error", "pathname": "/openstack/venvs/cinder-testing/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py", "context": {"domain": null, "project_name": null, "global_request_id": null, "project_domain": null, "timestamp": "2018-08-15T10:33:31.089453", "user_domain_name": null, "remote_address": null, "quota_class": null, "resource_uuid": null, "is_admin": true, "user": null, "service_catalog": [], "domain_id": null, "tenant": null, "read_only": false, "user_domain": null, "user_id": null, "show_deleted": false, "system_scope": null, "user_identity": "- - - - -", "domain_name": null, "is_admin_project": true, "project": null, "read_deleted": "no", "request_id": "req-e0d7fde8-a2cb-47a8-b12f-725a880d7a83", "roles": ["admin"], "project_id": null, "user_name": null, "auth_token": null, "project_domain_name": null}, "levelname": "ERROR"}

It looks like it is all happening here:

https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L739-L751

More specifically, getting it from this function:

https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L740

going up the stack..

https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L1143-L1156

going further up where self.connection is defined

https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L563-L580

going all the way up to kombu

https://github.com/celery/kombu/blob/master/kombu/connection.py#L625-L627

and this is where the leaked data comes from..

https://github.com/celery/kombu/blob/master/kombu/connection.py#L595-L623

[Mohammed Naser (mnaser)]

FWIW, oslo.log started including the JSON logger in 3.33.0

https://github.com/openstack/oslo.log/commit/215cc3a8ec5cb61a365a98d731d08ae2f13d46d1

This has been introduced in the Queens release.

[Ben Nemec (bnemec)]

Actually the JSON logger has been around quite a bit longer than that. There's an old bug against oslo.log for this: https://bugs.launchpad.net/oslo.log/+bug/1571714

I've subscribed you to that one so you should be able to see it now.

I left some thoughts on it, but the TLDR is that we should probably be running the args dict through mask_dict_password to catch as much as we can, have oslo.messaging explicitly filter this structure before passing it, and document that this is a possibility with the JSON logger for future situations where someone might pass sensitive data.

Addressing this has been on my todo list for quite a while but I have to admit it to dragging my feet on it because it's such an old bug. I will try to get some patches written up ASAP.

[Jeremy Stanley (fungi)]

Should this be marked as a duplicate of bug 1571714 in that case? Does this require patching in both projects?

[Ken Giusti (kgiusti)]

Yikes - that behavior of logging the entire 'info' dict wasn't expected (at least by me).

IMHO the logger has no business dumping the entire contents of that dict, esp. given that the intent is to provide only the selected fields.

In any case I think it's reasonable to have the rabbit driver curate the retrieved connection info to only those fields that matter - patch coming shortly....

[Ben Nemec (bnemec)]

I guess we might as well make these public since the patch is out there now?

[Ken Giusti (kgiusti)]

I'd rather not make this public for two reasons:

1) oslo.messaging patch hasn't been approved nor released
2) what about oslo.log? Should it be patched to avoid dumping all args to the log (i.e. changed only log what is referenced in the log format)? I wasn't aware of the current behavior and I suspect there may be other logging calls that end up outputting unintended information as well.

That said I admit I'm ignorant of how this project deals with security related issues. My experience with Apache is that the bug remains embargoed until after a release containing the fix has been made available...

[Ken Giusti (kgiusti)]

Also for some reason launchpad isn't picking up the review page:

https://review.openstack.org/#/c/593691/

[Ben Nemec (bnemec)]

Well, the patch is public so the issue is no longer secret. The privateness of this bug is also why the patch doesn't show up here. The bot can't access the bug to update it.

I don't know if you could see https://bugs.launchpad.net/oslo.log/+bug/1571714 but I've subscribed you so you should be able to now. I proposed dropping the args and msg fields from the JSONFormatter output as neither is intended to be formatted and args in particular will probably cause more problems like this in the future. I think that patch and your patch combined should wrap this up. I haven't submitted it yet as I want to get some general concensus on the approach first.

[Jeremy Stanley (fungi)]

Ken: The process recommended by the OpenStack Vulnerability Management Team is documented at https://security.openstack.org/vmt-process.html (though since oslo.log and oslo.messaging haven't applied for VMT oversight they're not necessarily obliged to follow the timeline described there).

[Ken Giusti (kgiusti)]

Thanks Jeremy,

/me reads....

A fix is proposed as a patch to the current master branch (as well as any
> affected supported branches) and attached to the private bug report, not
> sent to the public code review system.
>

Aww crap....

On Wed, Aug 22, 2018 at 12:41 PM Jeremy Stanley <email address hidden> wrote:

> Ken: The process recommended by the OpenStack Vulnerability Management
> Team is documented at https://security.openstack.org/vmt-process.html
> (though since oslo.log and oslo.messaging haven't applied for VMT
> oversight they're not necessarily obliged to follow the timeline
> described there).
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1787214
>
> Title:
> Using use_json logging leaks credentials
>
> Status in oslo.log:
> Triaged
> Status in oslo.messaging:
> In Progress
>
> Bug description:
> The following was observed in the OpenStack Ansible CI when use_json
> was used in oslo.log, it looks like it passes out all the items
> serialized which can cause credentials to be leaked:
>
> http://logs.openstack.org/61/591961/2/check/openstack-ansible-
> functional-ubuntu-xenial/f1781ce/logs/host/cinder-
> volume.service.journal.log.txt.gz#_Aug_15_11_10_32
>
> [in case it gets deleted]
>
> Aug 15 11:10:33 ubuntu-xenial-ovh-gra1-0001333882 cinder-
> volume[23478]: {"thread_name": "MainThread", "extra": {"project":
> "unknown", "version": "unknown"}, "process": 23478,
> "relative_created": 2235828.4900188446, "module": "impl_rabbit",
> "message": "[31818cce-51f4-402c-ad62-f3674460d470] Reconnected to AMQP
> server on 10.1.1.101:5672 via [amqp] client with port 54050.",
> "hostname": "ubuntu-xenial-ovh-gra1-0001333882", "filename":
> "impl_rabbit.py", "levelno": 20, "lineno": 778, "asctime": "2018-08-15
> 11:10:33", "msg": "[%(connection_id)s] Reconnected to AMQP server on
> %(hostname)s:%(port)s via [%(transport)s] client with port
> %(client_port)s.", "error_summary": "", "args": {"hostname":
> "10.1.1.101", "userid": "cinder", "password": "secrete",
> "virtual_host": "/cinder", "port": 5672, "insist": false, "ssl":
> false, "transport": "amqp", "connect_timeout": 5, "transport_options":
> {"on_blocked": "<function _on_connection_blocked at 0x7fb2fc3282a8>",
> "on_unblocked": "<function _on_connection_unblocked at
> 0x7fb2fc328320>", "client_properties": {"connection_name": "cinder-
> volume:23478:31818cce-51f4-402c-ad62-f3674460d470", "capabilities":
> {"connection.blocked": true, "authentication_failure_close": true,
> "consumer_cancel_notify": true}}, "confirm_publish": true},
> "login_method": "AMQPLAIN", "uri_prefix": null, "heartbeat": 60.0,
> "failover_strategy": "round-robin", "alternates": [], "client_port":
> 54050, "connection_id": "31818cce-51f4-402c-ad62-f3674460d470"},
> "process_name": "MainProcess", "name":
> "oslo.messaging._drivers.impl_rabbit", "thread": 140406697963024,
> "created": 1534331433.086563, "traceback": null, "msecs":
> 86.5631103515625, "funcname": "on_reconnection", "pathname":
> "/openstack/venvs/cinder-testing/local/lib/python2.7/site-
> packages/oslo_messaging...

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/596850
Committed: https://git.openstack.org/cgit/openstack/oslo.log/commit/?id=a93c6ef98c8aeddc5a4ae87083689225fbc728bb
Submitter: Zuul
Branch: master

commit a93c6ef98c8aeddc5a4ae87083689225fbc728bb
Author: Ben Nemec <email address hidden>
Date: Mon Aug 27 17:44:40 2018 +0000

    Filter args dict in JSONFormatter

    In most formatters, any unused keys in the args dict will just be
    discarded. Because JSONFormatter logged the entire dict in addition
    to the message, some values were included in the output that may
    not have been intended. This could include sensitive data, so we
    should stop that.

    In the interest of maintaining compatibility with any tools that are
    reading the args dict, we leave the dict but filter out any unused
    keys.

    Change-Id: Ib64837c1ae93a27bef3d30a776320a373f18dd1c
    Closes-Bug: 1571714
    Closes-Bug: 1787214

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/595338
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=95bcaca4b9775afa9aab62406c0e28b7793f25a6
Submitter: Zuul
Branch: stable/queens

commit 95bcaca4b9775afa9aab62406c0e28b7793f25a6
Author: Kenneth Giusti <email address hidden>
Date: Mon Aug 20 12:31:16 2018 -0400

    Avoid logging passwords on connection events

    Change-Id: I15c8c4a1177c363283281d2fed63545658eda5de
    Closes-Bug: #1787214
    (cherry picked from commit d9866029a2aab2c5f001100813c0425b4905fdf6)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/595341
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=d03b85e9d63702bbf0c416603f2f705e772dc7da
Submitter: Zuul
Branch: stable/pike

commit d03b85e9d63702bbf0c416603f2f705e772dc7da
Author: Kenneth Giusti <email address hidden>
Date: Mon Aug 20 12:31:16 2018 -0400

    Avoid logging passwords on connection events

    Change-Id: I15c8c4a1177c363283281d2fed63545658eda5de
    Closes-Bug: #1787214
    (cherry picked from commit d9866029a2aab2c5f001100813c0425b4905fdf6)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/595343
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=4b568352eb9498edac70c428e8638f50bb034789
Submitter: Zuul
Branch: stable/ocata

commit 4b568352eb9498edac70c428e8638f50bb034789
Author: Kenneth Giusti <email address hidden>
Date: Mon Aug 20 12:31:16 2018 -0400

    Avoid logging passwords on connection events

    Change-Id: I15c8c4a1177c363283281d2fed63545658eda5de
    Closes-Bug: #1787214
    (cherry picked from commit d9866029a2aab2c5f001100813c0425b4905fdf6)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/598338

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/598338
Committed: https://git.openstack.org/cgit/openstack/oslo.log/commit/?id=871d2df290d829b9cafb0dc383dc3d65810c2dac
Submitter: Zuul
Branch: stable/rocky

commit 871d2df290d829b9cafb0dc383dc3d65810c2dac
Author: Ben Nemec <email address hidden>
Date: Mon Aug 27 17:44:40 2018 +0000

    Filter args dict in JSONFormatter

    In most formatters, any unused keys in the args dict will just be
    discarded. Because JSONFormatter logged the entire dict in addition
    to the message, some values were included in the output that may
    not have been intended. This could include sensitive data, so we
    should stop that.

    In the interest of maintaining compatibility with any tools that are
    reading the args dict, we leave the dict but filter out any unused
    keys.

    Change-Id: Ib64837c1ae93a27bef3d30a776320a373f18dd1c
    Closes-Bug: 1571714
    Closes-Bug: 1787214
    (cherry picked from commit a93c6ef98c8aeddc5a4ae87083689225fbc728bb)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 5.35.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 5.30.5 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.log 3.39.1 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 8.1.1 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.log 3.40.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 5.17.4 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.messaging 9.0.0 release.