Solum/Logging

In order to prevent accidental leakage of confidential information to unauthorized Solum users, there are some guidelines to assist in isolating this confidential data for easy/accurate filtering on the back end log management tools. Why is this important? There have been several OpenStack security issues around logging recently:

(Ceilometer) Log contains DB password in plain text (CVE-2013-6384) [OSSA 2013-031]
(Keystone) Plaintext passwords are logged
(Nova) Clear text password has been print in log by some API call

etc...

Logs should have a format that enables grouping of confidential data especially when logging data such as:

Exceptions: Unless the developer is sure that an exception will never contain confidential information, exceptions should be identified as confidential. This has historically been especially problematic with database exceptions which may contain real field data.
- Recommend parsing the specific exception or error and providing an abstracted/safe version back to the user
Passwords: Never log plain text passwords
Private Keys: Never log plain text private keys
PII: Minimize Personally Identifiable Information (PII) logging where possible
Local Server State: Avoid logging local server state which may provide hints to attackers (examples: file paths, code file names, user account names, PRNG state)
Tenant/Project ID Checking: If a user identifier (tenant/project ID) is not present in the log record or does not match the current authenticated user, do not show this log data to the user
Log Insecure Configurations: If a Solum configuration option causes the system to enter a potentially less secure state, log a message to this effect for operators to see

OpenStack's Oslo Log is capable of creating formatted logs with a section for confidential data. The following example contains two pieces of variable data: key_name which is not confidential data (and will equal 'ssh') and key_value which is a confidential key that should not be visible to anyone but Solum admins/operators.

Note: This is a contrived example for simplicity. If the key_value is a public ssh key, it probably isn't critical to hide it in the logs from the authorized user that it belongs to. If the key_value is a private ssh key, it shouldn't be logged to begin with.

Bad Example:

LOG.debug("User set %s key to value %s" % [key_name, key_value])

Revised/Good Example:

LOG.debug("User set %s key" % [key_name], extra={private={value=key_value}})

Note that the extra->private structure is used to hold all confidential data within logs so that it may be filtered out later before a user views logs. In this example, the key value is moved to a 'private' dictionary which makes filtering out confidential data from logs easier as there will be a single keyword to locate in log entries if Solum adheres to these guidelines. An authenticated user may see that an ssh key has been changed but a Solum operator may see the actual ssh key value in the logs.

Log level definitions: http://stackoverflow.com/questions/2031163/when-to-use-log-level-warn-vs-error This is a nice writeup about when to use each log level. Here is a brief description:

Debug: Shows everything and is likely not suitable for normal production operation due to the sheer size of logs generated
Info: Usually indicates successful service start/stop, versions and such non-error related data
Warning: Indicates that there might be a systemic issue; potential predictive failure notice
Error: An error has occurred and an administrator should research the event
Critical: An error has occurred and the system might be unstable; immediately get administrator assistance

Example of Oslo Log and Oslo Context:

This is an example of the combination of Oslo log and Oslo context

This demonstrates the ability to manipulate the context data which is logged and modify the format. This enables the ability to filter certain private data based on the log format used. When new context is added into RequestContext (or rather the inheriting class in most cases) the log format may be changed to add the new context into logs. The solum.conf.sample file has a logging_context_format_string configuration value that enables modifying context logging through a configuration file.

Pros

Uses all basic Oslo code and mimics other projects

Cons

Some Oslo RequestContext fields are likely not applicable to Solum and will need to be ignored
Potentially less intuitive control and identification of confidential data. Only Oslo Log's logging_context_format_string defines this.
- Reviewers must carefully scrutinize all future logging entries in order to succeed in preventing leakage of confidential data.

from oslo.config import cfg
from solum.openstack.common import context
from solum.openstack.common import log

LOG = log.getLogger(__name__)
log.setup('solum')
CONTEXT = context.RequestContext(user='John Doe', tenant='test tenant')
LOG.error('Standard context log output', context=CONTEXT)

CONF = cfg.CONF
CONF.logging_context_format_string = (
    "%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s "
    "{'private': {'user': %(user)s, 'tenant': %(tenant)s}} "
    "%(instance)s%(message)s]}")
LOG.error('Modified context log output', context=CONTEXT)

Output:

2014-01-23 20:48:30.156 22345 ERROR __main__ [req-1a007cc5-cce8-4a63-8572-99e1148c784c John Doe test tenant] Standard context log output
2014-01-23 20:48:30.157 22345 ERROR __main__ {'private': {'user': John Doe, 'tenant': test tenant}} Modified context log output]}

Example of Oslo Log and Oslo Context Combined with SecurityContext:

SecurityContext inherits Oslo RequestContext and addes some of the features from this pull request: https://review.openstack.org/#/c/63201/ ... which identifies public (users may see logs/notifications of this data) vs private (only Solum operators can see this data).

Note: This is not tested, internationalized, uses the wrong exceptions, etc. It is simply an example of possible architecture to discuss with the community.

Pros

Easy, intuitive identification and classification of confidential data
Basic confidentiality enforcement for get_pub() and get_priv() (get_pub() of confidential data will cause an exception)
Extensible to add more context fields simply by using set_pub() or set_priv()
Automatic structured context logging output
Can add clearing of confidential data memory once done with field
The designation of what data is public/private happens at the time the data is placed into the security context, rather than at logging time. This is safer than doing it at logging time.

Cons

Perhaps a little too much overhead/over-engineered
Performance hit?
Might be complexity in this integration that hasn't been discovered yet

Main:

from oslo.config import cfg
from solum import security_context
from solum.openstack.common import log

LOG = log.getLogger(__name__)
log.setup('solum')
CONTEXT = security_context.SecurityContext()
CONTEXT.set_pub(user='Bill', blahkey='blah value')
CONF = cfg.CONF
CONF.logging_context_format_string = (
    "%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s "
    "---%(public_context)s---, ===%(private_context)s=== "
    "%(instance)s%(message)s]}")
LOG.error('Modified context log output', context=CONTEXT)

print CONTEXT.get_pub('user')
print "Now an error case, try to get user from private data..."
print CONTEXT.get_priv('user')

SecurityContext class:

from solum.openstack.common import context


class SecurityContext(context.RequestContext):
    def __init__(self):
        super(self.__class__, self).__init__()
        self.read_only = None
        self.show_deleted = None
        self.is_admin = None
        self._priv_data = {}
        self._pub_data = {}

    def set_pub(self, **kwargs):
        for key, val in kwargs.iteritems():
            if key in self._priv_data:
                raise Exception("%s was previously marked as private." % (
                    key))
            self.__dict__[key] = val
            self._pub_data[key] = val

    def get_pub(self, search_key):
        return self._pub_data[search_key]

    def set_priv(self, **kwargs):
        for key, val in kwargs.iteritems():
            if key in self._pub_data:
                raise Exception("%s was previously marked as public." % (
                    key))
            self.__dict__[key] = val
            self._priv_data[key] = val

    def get_priv(self, search_key):
        return self._priv_data[search_key]

    def to_dict(self):
        # Oslo Log requires a 'request_id' value!
        return {'request_id': self.request_id,
                'public_context': self._pub_data,
                'private_context': self._priv_data}

Output:

2014-01-27 21:40:07.641 8206 ERROR __main__ ---{'user': 'Bill', 'blahkey': 'blah value'}---, ==={}=== Modified context log output]}
Bill
Now an error case, try to get user from private data...
2014-01-27 21:40:07.642 8206 CRITICAL solum [-] 'user'

Solum/Logging

Contents

Example of Oslo Log and Oslo Context:

Example of Oslo Log and Oslo Context Combined with SecurityContext: