feat(logging): Enhance logging and update grpcio

Enhance request logging (and scrub sensitive headers)
Enhance Tiller logging
Update grpcio, unpin from 1.6.0rc1

Plus a couple typo fixes
Plus a couple unused vars

Change-Id: I8afd679f6716c6e1af234a59ac44ba1fdc73cdc8
This commit is contained in:
Marshall Margenau 2018-03-06 18:55:35 -06:00 committed by Scott Hussey
parent 59ae1fd767
commit 3430283865
14 changed files with 134 additions and 55 deletions

View File

@ -16,12 +16,14 @@ import json
import falcon
from oslo_config import cfg
from oslo_log import log as logging
from armada import api
from armada.common import policy
from armada.handlers.tiller import Tiller
CONF = cfg.CONF
LOG = logging.getLogger(__name__)
class Status(api.BaseResource):
@ -38,6 +40,10 @@ class Status(api.BaseResource):
tiller_namespace=req.get_param(
'tiller_namespace', default=CONF.tiller_namespace))
LOG.debug('Tiller (Status) at: %s:%s, namespace=%s, '
'timeout=%s', tiller.tiller_host, tiller.tiller_port,
tiller.tiller_namespace, tiller.timeout)
message = {
'tiller': {
'state': tiller.tiller_status(),
@ -69,6 +75,10 @@ class Release(api.BaseResource):
tiller_namespace=req.get_param(
'tiller_namespace', default=CONF.tiller_namespace))
LOG.debug('Tiller (Release) at: %s:%s, namespace=%s, '
'timeout=%s', tiller.tiller_host, tiller.tiller_port,
tiller.tiller_namespace, tiller.timeout)
releases = {}
for release in tiller.list_releases():
releases.setdefault(release.namespace, [])

View File

@ -12,6 +12,8 @@
# See the License for the specific language governing permissions and
# limitations under the License.
import re
from uuid import UUID
from oslo_config import cfg
@ -97,7 +99,24 @@ class LoggingMiddleware(object):
def __init__(self):
self.logger = logging.getLogger(__name__)
# don't log any headers beginning with X-*
hdr_exclude = re.compile('x-.*', re.IGNORECASE)
def process_request(self, req, resp):
""" Set up values to be logged across the request
"""
ctx = req.context
extra = {
'user': ctx.user,
'req_id': ctx.request_id,
'external_ctx': ctx.external_marker,
}
self.logger.info("Request %s %s" % (req.method, req.url), extra=extra)
self._log_headers(req.headers)
def process_response(self, req, resp, resource, req_succeeded):
""" Log the response information
"""
ctx = req.context
extra = {
'user': ctx.user,
@ -105,4 +124,13 @@ class LoggingMiddleware(object):
'external_ctx': ctx.external_marker,
}
resp.append_header('X-Armada-Req', ctx.request_id)
self.logger.info("%s - %s" % (req.uri, resp.status), extra=extra)
self.logger.info("%s %s - %s" % (req.method, req.uri, resp.status),
extra=extra)
self.logger.debug("Response body:%s", resp.body)
def _log_headers(self, headers):
""" Log request headers, while scrubbing sensitive values
"""
for header, header_value in headers.items():
if not LoggingMiddleware.hdr_exclude.match(header):
self.logger.debug("Header %s: %s", header, header_value)

View File

@ -36,7 +36,7 @@ CONF = cfg.CONF
def create(enable_middleware=CONF.middleware):
"""Entry point for intializing Armada server.
"""Entry point for initializing Armada server.
:param enable_middleware: Whether to enable middleware.
:type enable_middleware: bool
@ -47,8 +47,8 @@ def create(enable_middleware=CONF.middleware):
request_type=ArmadaRequest,
middleware=[
AuthMiddleware(),
ContextMiddleware(),
LoggingMiddleware(),
ContextMiddleware()
])
else:
api = falcon.API(request_type=ArmadaRequest)

View File

@ -19,22 +19,22 @@ armada_policies = [
policy.DocumentedRuleDefault(
name=base.ARMADA % 'create_endpoints',
check_str=base.RULE_ADMIN_REQUIRED,
description='install manifest charts',
description='Install manifest charts',
operations=[{'path': '/api/v1.0/apply/', 'method': 'POST'}]),
policy.DocumentedRuleDefault(
name=base.ARMADA % 'validate_manifest',
check_str=base.RULE_ADMIN_REQUIRED,
description='validate installed manifest',
description='Validate manifest',
operations=[{'path': '/api/v1.0/validatedesign/', 'method': 'POST'}]),
policy.DocumentedRuleDefault(
name=base.ARMADA % 'test_release',
check_str=base.RULE_ADMIN_REQUIRED,
description='validate install manifest',
description='Test release',
operations=[{'path': '/api/v1.0/test/{release}', 'method': 'GET'}]),
policy.DocumentedRuleDefault(
name=base.ARMADA % 'test_manifest',
check_str=base.RULE_ADMIN_REQUIRED,
description='validate install manifest',
description='Test manifest',
operations=[{'path': '/api/v1.0/tests/', 'method': 'POST'}]),
]

View File

@ -73,9 +73,13 @@ class ArmadaSession(object):
:return: A requests.Response object
"""
api_url = '{}{}'.format(self.base_url, endpoint)
req_timeout = self._timeout(timeout)
self.logger.debug("Sending armada_client session GET %s with "
"params=[%s], headers=[%s], timeout=[%s]",
api_url, query, headers, req_timeout)
resp = self._session.get(
api_url, params=query, headers=headers,
timeout=self._timeout(timeout))
api_url, params=query, headers=headers, timeout=req_timeout)
return resp
@ -95,22 +99,25 @@ class ArmadaSession(object):
:return: A requests.Response object
"""
api_url = '{}{}'.format(self.base_url, endpoint)
req_timeout = self._timeout(timeout)
self.logger.debug("Sending POST with armada_client session")
self.logger.debug("Sending armada_client session POST %s with "
"params=[%s], headers=[%s], timeout=[%s]",
api_url, query, headers, req_timeout)
if body is not None:
self.logger.debug("Sending POST with explicit body: \n%s" % body)
resp = self._session.post(api_url,
params=query,
data=body,
headers=headers,
timeout=self._timeout(timeout))
timeout=req_timeout)
else:
self.logger.debug("Sending POST with JSON body: \n%s" % str(data))
resp = self._session.post(api_url,
params=query,
json=data,
headers=headers,
timeout=self._timeout(timeout))
timeout=req_timeout)
return resp

View File

@ -22,7 +22,6 @@ from oslo_log import log as logging
LOG = logging.getLogger(__name__)
DEFAULT_TIMEOUT = 3600
CONF = cfg.CONF
@ -153,7 +152,7 @@ def default_error_serializer(req, resp, exception):
def default_exception_handler(ex, req, resp, params):
"""
Catch-all execption handler for standardized output.
Catch-all exception handler for standardized output.
If this is a standard falcon HTTPError, rethrow it for handling
"""
if isinstance(ex, falcon.HTTPError):
@ -219,7 +218,7 @@ class AppError(Exception):
@staticmethod
def _gen_ex_message(title, description):
ttl = title or 'Exception'
dsc = description or 'No additional decsription'
dsc = description or 'No additional description'
return '{} : {}'.format(ttl, dsc)
@staticmethod

View File

@ -19,8 +19,6 @@ from oslo_log import log as logging
from armada.common.i18n import _
LOG = logging.getLogger(__name__)
DEFAULT_TIMEOUT = 3600
CONF = cfg.CONF

View File

@ -26,7 +26,7 @@ LOG = logging.getLogger(__name__)
class ReferenceResolver(object):
"""Class for handling different data references to resolve them data."""
"""Class for handling different data references to resolve the data."""
@classmethod
def resolve_reference(cls, design_ref):
@ -36,6 +36,7 @@ class ReferenceResolver(object):
and use that handler to get the data referenced.
:param design_ref: A list of URI-formatted reference to a data entity
:returns: A list of byte arrays
"""
data = []

View File

@ -306,8 +306,8 @@ class K8s(object):
LOG.debug('Pod %s is ready!', pod_name)
else:
pod_ready = False
LOG.debug('Pod %s not ready: conditions=[%s] '
'container_statuses=[%s] ', pod_name,
LOG.debug('Pod %s not ready: conditions:\n%s\n'
'container_statuses:\n%s', pod_name,
status.conditions, status.container_statuses)
ready_pods[pod_name] = pod_ready

View File

@ -65,7 +65,7 @@ class Tiller(object):
# init k8s connectivity
self.k8s = K8s()
# init tiller channel
# init Tiller channel
self.channel = self.get_channel()
# init timeout for all requests
@ -73,20 +73,29 @@ class Tiller(object):
# be fed at runtime as an override
self.timeout = TILLER_TIMEOUT
LOG.debug('Armada is using Tiller at: %s:%s, namespace=%s, timeout=%s',
self.tiller_host, self.tiller_port, self.tiller_namespace,
self.timeout)
@property
def metadata(self):
'''
Return tiller metadata for requests
Return Tiller metadata for requests
'''
return [(b'x-helm-api-client', TILLER_VERSION)]
def get_channel(self):
'''
Return a tiller channel
Return a Tiller channel
'''
tiller_ip = self._get_tiller_ip()
tiller_port = self._get_tiller_port()
try:
LOG.debug('Tiller getting gRPC insecure channel at %s:%s '
'with options: [grpc.max_send_message_length=%s, '
'grpc.max_receive_message_length=%s]',
tiller_ip, tiller_port,
MAX_MESSAGE_LENGTH, MAX_MESSAGE_LENGTH)
return grpc.insecure_channel(
'%s:%s' % (tiller_ip, tiller_port),
options=[
@ -99,49 +108,56 @@ class Tiller(object):
def _get_tiller_pod(self):
'''
Returns tiller pod using the tiller pod labels specified in the Armada
Returns Tiller pod using the Tiller pod labels specified in the Armada
config
'''
pods = None
namespace = self._get_tiller_namespace()
pods = self.k8s.get_namespace_pod(namespace,
CONF.tiller_pod_labels).items
# No tiller pods found
# No Tiller pods found
if not pods:
raise ex.TillerPodNotFoundException(CONF.tiller_pod_labels)
# Return first tiller pod in running state
# Return first Tiller pod in running state
for pod in pods:
if pod.status.phase == 'Running':
LOG.debug('Found at least one Running Tiller pod.')
return pod
# No tiller pod found in running state
# No Tiller pod found in running state
raise ex.TillerPodNotRunningException()
def _get_tiller_ip(self):
'''
Returns the tiller pod's IP address by searching all namespaces
Returns the Tiller pod's IP address by searching all namespaces
'''
if self.tiller_host:
LOG.debug('Using Tiller host IP: %s', self.tiller_host)
return self.tiller_host
else:
pod = self._get_tiller_pod()
LOG.debug('Using Tiller pod IP: %s', pod.status.pod_ip)
return pod.status.pod_ip
def _get_tiller_port(self):
'''Stub method to support arbitrary ports in the future'''
LOG.debug('Using Tiller host port: %s', self.tiller_port)
return self.tiller_port
def _get_tiller_namespace(self):
LOG.debug('Using Tiller namespace: %s', self.tiller_namespace)
return self.tiller_namespace
def tiller_status(self):
'''
return if tiller exist or not
return if Tiller exist or not
'''
if self._get_tiller_ip():
LOG.debug('Getting Tiller Status: Tiller exists')
return True
LOG.debug('Getting Tiller Status: Tiller does not exist')
return False
def list_releases(self):
@ -155,10 +171,13 @@ class Tiller(object):
STATUS_FAILED],
sort_by='LAST_RELEASED',
sort_order='DESC')
LOG.debug('Tiller ListReleases() with timeout=%s', self.timeout)
release_list = stub.ListReleases(req, self.timeout,
metadata=self.metadata)
for y in release_list:
LOG.debug('Found release: %s', y.releases)
releases.extend(y.releases)
return releases
@ -206,7 +225,7 @@ class Tiller(object):
name, release_name, namespace, labels,
action_type, chart, disable_hooks, values)
except Exception:
LOG.debug("Pre: Could not update anything, please check yaml")
LOG.warn("Pre: Could not update anything, please check yaml")
try:
for action in actions.get('delete', []):
@ -217,7 +236,7 @@ class Tiller(object):
self.delete_resources(
release_name, name, action_type, labels, namespace)
except Exception:
LOG.debug("PRE: Could not delete anything, please check yaml")
LOG.warn("PRE: Could not delete anything, please check yaml")
raise ex.PreUpdateJobDeleteException(name, namespace)
try:
@ -230,7 +249,7 @@ class Tiller(object):
self.k8s.create_job_action(name, action_type)
continue
except Exception:
LOG.debug("PRE: Could not create anything, please check yaml")
LOG.warn("PRE: Could not create anything, please check yaml")
raise ex.PreUpdateJobCreateException(name, namespace)
def _post_update_actions(self, actions, namespace):
@ -244,7 +263,7 @@ class Tiller(object):
self.k8s.create_job_action(name, action_type)
continue
except Exception:
LOG.debug("POST: Could not create anything, please check yaml")
LOG.warn("POST: Could not create anything, please check yaml")
raise ex.PreUpdateJobCreateException(name, namespace)
def list_charts(self):
@ -264,6 +283,7 @@ class Tiller(object):
latest_release.info.status.code)))
except IndexError:
continue
LOG.debug('List of Helm Charts from Latest Releases: %s', charts)
return charts
def update_release(self, chart, release, namespace,
@ -280,8 +300,9 @@ class Tiller(object):
rel_timeout = self.timeout if not timeout else timeout
LOG.debug("wait: %s", wait)
LOG.debug("timeout: %s", timeout)
LOG.debug('Helm update release%s: wait=%s, timeout=%s',
(' (dry run)' if dry_run else ''),
wait, timeout)
if values is None:
values = Config(raw='')
@ -323,7 +344,9 @@ class Tiller(object):
rel_timeout = self.timeout if not timeout else timeout
LOG.info("Wait: %s, Timeout: %s", wait, timeout)
LOG.debug('Helm install release%s: wait=%s, timeout=%s',
(' (dry run)' if dry_run else ''),
wait, timeout)
if values is None:
values = Config(raw='')
@ -356,9 +379,10 @@ class Tiller(object):
:param cleanup - removes testing pod created
:returns - results of test pod
'''
LOG.debug("Helm test release %s, timeout=%s", release, timeout)
try:
stub = ReleaseServiceStub(self.channel)
@ -391,16 +415,20 @@ class Tiller(object):
'''
:param release - name of release to test
:param version - version of release status
'''
LOG.debug('Helm getting release status for release=%s, version=%s',
release, version)
try:
stub = ReleaseServiceStub(self.channel)
status_request = GetReleaseStatusRequest(
name=release, version=version)
LOG.debug('GetReleaseStatusRequest= %s', status_request)
return stub.GetReleaseStatus(
release_status = stub.GetReleaseStatus(
status_request, self.timeout, metadata=self.metadata)
LOG.debug('GetReleaseStatus= %s', release_status)
return release_status
except Exception:
raise ex.GetReleaseStatusException(release, version)
@ -409,42 +437,51 @@ class Tiller(object):
'''
:param release - name of release to test
:param version - version of release status
'''
LOG.debug('Helm getting release content for release=%s, version=%s',
release, version)
try:
stub = ReleaseServiceStub(self.channel)
status_request = GetReleaseContentRequest(
name=release, version=version)
LOG.debug('GetReleaseContentRequest= %s', status_request)
return stub.GetReleaseContent(
release_content = stub.GetReleaseContent(
status_request, self.timeout, metadata=self.metadata)
LOG.debug('GetReleaseContent= %s', release_content)
return release_content
except Exception:
raise ex.GetReleaseContentException(release, version)
def tiller_version(self):
'''
:returns - tiller version
:returns - Tiller version
'''
try:
stub = ReleaseServiceStub(self.channel)
release_request = GetVersionRequest()
LOG.debug('Getting Tiller version, with timeout=%s', self.timeout)
tiller_version = stub.GetVersion(
release_request, self.timeout, metadata=self.metadata)
LOG.debug('Got Tiller version response: %s', tiller_version)
return getattr(tiller_version.Version, 'sem_ver', None)
tiller_version = getattr(tiller_version.Version, 'sem_ver', None)
LOG.debug('Got Tiller version %s', tiller_version)
return tiller_version
except Exception:
LOG.debug('Failed to get Tiller version')
raise ex.TillerVersionException()
def uninstall_release(self, release, disable_hooks=False, purge=True):
'''
:params - release - helm chart release name
:params - release - Helm chart release name
:params - purge - deep delete of chart
deletes a helm chart from tiller
deletes a Helm chart from Tiller
'''
# build release install request

View File

@ -33,11 +33,11 @@ class TillerControllerTest(base.BaseControllerTest):
self.policy.set_rules(rules)
mock_tiller.return_value.tiller_status.return_value = 'fake_status'
mock_tiller.return_value.tiller_version.return_value = 'fake_verson'
mock_tiller.return_value.tiller_version.return_value = 'fake_version'
result = self.app.simulate_get('/api/v1.0/status')
expected = {
'tiller': {'version': 'fake_verson', 'state': 'fake_status'}
'tiller': {'version': 'fake_version', 'state': 'fake_status'}
}
self.assertEqual(expected, result.json)
@ -53,7 +53,7 @@ class TillerControllerTest(base.BaseControllerTest):
self.policy.set_rules(rules)
mock_tiller.return_value.tiller_status.return_value = 'fake_status'
mock_tiller.return_value.tiller_version.return_value = 'fake_verson'
mock_tiller.return_value.tiller_version.return_value = 'fake_version'
result = self.app.simulate_get('/api/v1.0/status',
params_csv=False,
@ -61,7 +61,7 @@ class TillerControllerTest(base.BaseControllerTest):
'tiller_port': '98765',
'tiller_namespace': 'fake_ns'})
expected = {
'tiller': {'version': 'fake_verson', 'state': 'fake_status'}
'tiller': {'version': 'fake_version', 'state': 'fake_status'}
}
self.assertEqual(expected, result.json)

View File

@ -12,7 +12,6 @@
# See the License for the specific language governing permissions and
# limitations under the License.
# import mock
import testtools
import responses

View File

@ -56,7 +56,7 @@ def _validate_armada_manifest(manifest):
:class:`armada.handlers.manifest.Manifest`.
This will do business logic validation after the input
files have be syntatically validated via jsonschema.
files have be syntactically validated via jsonschema.
:param dict manifest: The manifest to validate.
@ -97,7 +97,7 @@ def _validate_armada_manifest(manifest):
def validate_armada_manifests(documents):
"""Validate each Aramada manifest found in the document set.
"""Validate each Armada manifest found in the document set.
:param documents: List of Armada documents to validate
:type documents: :func: `list[dict]`.
@ -170,7 +170,7 @@ def validate_armada_document(document):
def validate_armada_documents(documents):
"""Validates multiple Armada documents.
:param documents: List of Armada maanifests to validate.
:param documents: List of Armada manifests to validate.
:type documents: :func:`list[dict]`.
:returns: A tuple of bool, list[dict] where the first value is whether

View File

@ -1,6 +1,6 @@
gitpython
grpcio==1.6.0rc1
grpcio-tools==1.6.0rc1
grpcio>=1.6.0
grpcio-tools>=1.6.0
keystoneauth1==2.21.0
keystonemiddleware==4.9.1
kubernetes>=1.0.0