diff --git a/entrypoint.sh b/entrypoint.sh index 8e77e100..c26b4bdf 100755 --- a/entrypoint.sh +++ b/entrypoint.sh @@ -23,7 +23,9 @@ if [ "$1" = 'server' ]; then --paste config:/etc/promenade/api-paste.ini \ --enable-threads \ --threads "${PROMENADE_THREADS}" \ - --workers "${PROMENADE_WORKERS}" + --workers "${PROMENADE_WORKERS}" \ + --logger "null file:/dev/null" \ + --log-route "null health" fi exec ${@} diff --git a/promenade/config.py b/promenade/config.py index 6553077d..6a0da17b 100644 --- a/promenade/config.py +++ b/promenade/config.py @@ -60,8 +60,8 @@ class Configuration: return cls(documents=documents, **kwargs) @classmethod - def from_design_ref(cls, design_ref, **kwargs): - documents, use_dh_engine = dr.get_documents(design_ref) + def from_design_ref(cls, design_ref, ctx=None, **kwargs): + documents, use_dh_engine = dr.get_documents(design_ref, ctx) return cls( documents=documents, diff --git a/promenade/control/base.py b/promenade/control/base.py index f25e5dcf..c99e554d 100644 --- a/promenade/control/base.py +++ b/promenade/control/base.py @@ -95,10 +95,10 @@ class PromenadeRequestContext(context.RequestContext): Context object for promenade resource requests """ - def __init__(self, external_marker=None, policy_engine=None, **kwargs): + def __init__(self, context_marker=None, policy_engine=None, **kwargs): self.log_level = 'error' self.request_id = str(uuid.uuid4()) - self.external_marker = external_marker + self.context_marker = context_marker self.policy_engine = policy_engine self.is_admin_project = False self.authenticated = False @@ -123,8 +123,14 @@ class PromenadeRequestContext(context.RequestContext): def remove_role(self, role): self.roles = [x for x in self.roles if x != role] - def set_external_marker(self, marker): - self.external_marker = marker + def set_context_marker(self, context_marker): + self.context_marker = context_marker + + def set_request_id(self, request_id): + self.request_id = request_id + + def set_end_user(self, end_user): + self.end_user = end_user def set_policy_engine(self, engine): self.policy_engine = engine @@ -144,9 +150,10 @@ class PromenadeRequestContext(context.RequestContext): def to_log_context(self): result = {} - result['request_id'] = self.request_id - result['external_id'] = self.external_marker - result['user'] = self.user + result['request_id'] = getattr(self, 'request_id', None) + result['context_marker'] = getattr(self, 'context_marker', None) + result['end_user'] = getattr(self, 'end_user', None) + result['user'] = getattr(self, 'user', None) return result diff --git a/promenade/control/middleware.py b/promenade/control/middleware.py index 23f92c8a..0bd1e697 100644 --- a/promenade/control/middleware.py +++ b/promenade/control/middleware.py @@ -26,8 +26,10 @@ class AuthMiddleware(object): ctx = req.context ctx.set_policy_engine(policy.policy_engine) - for k, v in req.headers.items(): - LOG.debug("Request with header %s: %s" % (k, v)) + # don't spam log with headers for health checks + if not req.url.endswith('/health'): + for k, v in req.headers.items(): + LOG.debug("Request with header %s: %s" % (k, v)) auth_status = req.get_header( 'X-SERVICE-IDENTITY-STATUS') # will be set to Confirmed or Invalid @@ -100,21 +102,69 @@ class ContextMiddleware(object): def process_request(self, req, resp): ctx = req.context - ext_marker = req.get_header('X-Context-Marker') - if ext_marker is not None and self._is_uuid_like(ext_marker): - # external passed in an ok context marker - ctx.set_external_marker(ext_marker) + context_marker = req.get_header('X-CONTEXT-MARKER') + end_user = req.get_header('X-END-USER') + if context_marker is not None: + ctx.set_context_marker(context_marker) else: - # use the request id - ctx.set_external_marker(ctx.request_id) + ctx.set_context_marker(ctx.request_id) + if end_user is not None: + ctx.set_end_user(end_user) + else: + ctx.set_end_user(ctx.user) class LoggingMiddleware(object): + def process_request(self, req, resp): + # don't log health checks + if not req.url.endswith('/health'): + ctx = req.context + LOG.info( + "Request: %s %s %s", + req.method, + req.uri, + req.query_string, + ctx=ctx) + def process_response(self, req, resp, resource, req_succeeded): ctx = req.context + # only log health check responses if the check failed + if req.url.endswith('/health'): + resp_code = self._get_resp_code(resp) + if not resp_code == 204: + LOG.error( + 'Health check has failed with response status %s', + resp.status, + ctx=ctx) + else: + context_marker = getattr(ctx, 'context_marker', None) + request_id = getattr(ctx, 'request_id', None) + user = getattr(ctx, 'user', None) + end_user = getattr(ctx, 'end_user', None) + if context_marker is not None: + resp.append_header('X-CONTEXT-MARKER', context_marker) + if request_id is not None: + resp.append_header('X-DECKHAND-REQ', request_id) + if end_user is not None: + resp.append_header('X-END-USER', end_user) + if user is not None: + resp.append_header('X-USER-NAME', user) + LOG.info( + "Response: %s %s %s", + req.method, + req.uri, + resp.status, + ctx=ctx) - resp.append_header('X-Promenade-Req', ctx.request_id) - LOG.info('%s %s - %s', req.method, req.uri, resp.status, ctx=ctx) + def _get_resp_code(self, resp): + # Falcon response object doesn't have a raw status code. + # Splits by the first space + try: + return int(resp.status.split(" ", 1)[0]) + except ValueError: + # if for some reason this Falcon response doesn't have a valid + # status, return a high value sentinel + return 9999 class NoAuthFilter(object): diff --git a/promenade/control/validatedesign.py b/promenade/control/validatedesign.py index 57c750d5..28321a2f 100644 --- a/promenade/control/validatedesign.py +++ b/promenade/control/validatedesign.py @@ -28,10 +28,11 @@ class ValidateDesignResource(base.BaseResource): def on_post(self, req, resp): result = ValidationMessage() try: + ctx = req.context json_data = self.req_json(req) href = json_data.get('href', None) config = Configuration.from_design_ref( - href, allow_missing_substitutions=False) + href, allow_missing_substitutions=False, ctx=ctx) result = validation.validate_all(config) except exceptions.InvalidFormatError as e: msg = "Invalid JSON Format: %s" % str(e) diff --git a/promenade/design_ref.py b/promenade/design_ref.py index c89eabf6..e6971460 100644 --- a/promenade/design_ref.py +++ b/promenade/design_ref.py @@ -14,15 +14,15 @@ _DECKHAND_PREFIX = 'deckhand+' DH_TIMEOUT = 10 * 60 # 10 Minute timeout for fetching from Deckhand. -def get_documents(design_ref): - LOG.debug('Fetching design_ref="%s"', design_ref) +def get_documents(design_ref, ctx=None): + LOG.debug('Fetching design_ref="%s"', design_ref, ctx=ctx) if design_ref.startswith(_DECKHAND_PREFIX): - response = _get_from_deckhand(design_ref) + response = _get_from_deckhand(design_ref, ctx) use_dh_engine = False else: response = _get_from_basic_web(design_ref) use_dh_engine = True - LOG.debug('Got response for design_ref="%s"', design_ref) + LOG.debug('Got response for design_ref="%s"', design_ref, ctx=ctx) response.raise_for_status() @@ -33,12 +33,20 @@ def _get_from_basic_web(design_ref): return requests.get(design_ref) -def _get_from_deckhand(design_ref): +def _get_from_deckhand(design_ref, ctx=None): keystone_args = {} for attr in ('auth_url', 'password', 'project_domain_name', 'project_name', 'username', 'user_domain_name'): keystone_args[attr] = cfg.CONF.get('keystone_authtoken', {}).get(attr) + if ctx is not None: + addl_headers = { + 'X-CONTEXT-MARKER': ctx.context_marker, + 'X-END-USER': ctx.end_user + } + else: + addl_headers = {} auth = keystoneauth1.identity.v3.Password(**keystone_args) - session = keystoneauth1.session.Session(auth=auth) + session = keystoneauth1.session.Session( + auth=auth, additional_headers=addl_headers) return session.get(design_ref[len(_DECKHAND_PREFIX):], timeout=DH_TIMEOUT) diff --git a/promenade/logging.py b/promenade/logging.py index 97e568cc..4fa31a35 100644 --- a/promenade/logging.py +++ b/promenade/logging.py @@ -4,12 +4,16 @@ import logging.config __all__ = ['getLogger', 'setup'] -LOG_FORMAT = '%(asctime)s %(levelname)-8s %(request_id)s %(external_id)s %(user)s %(name)s:%(filename)s:%(lineno)3d:%(funcName)s %(message)s' # noqa +LOG_FORMAT = '%(asctime)s %(levelname)-8s ' \ + 'req_id=%(request_id)s ctx=%(context_marker)s ' \ + 'end_user=%(end_user)s user=%(user)s ' \ + '%(name)s:%(filename)s:%(lineno)3d:%(funcName)s %(message)s' BLANK_CONTEXT_VALUES = [ - 'external_id', + 'context_marker', 'request_id', 'user', + 'end_user', ] DEFAULT_CONFIG = { diff --git a/requirements-direct.txt b/requirements-direct.txt index f23fbced..edcb9099 100644 --- a/requirements-direct.txt +++ b/requirements-direct.txt @@ -14,4 +14,4 @@ pbr==3.0.1 pyyaml==3.12 requests==2.18.4 uwsgi==2.0.15 -git+https://git.openstack.org/openstack/airship-deckhand@2f596fd62713bfd4149757a77a4943dd60b64cca +git+https://git.openstack.org/openstack/airship-deckhand@c1d0ff683ee94626b709954ad442b4f202f714d5