initial import for Open Source 🎉

util/metrics/metricqueue.py

@@ -0,0 +1,210 @@
+import datetime
+import logging
+import time
+
+from functools import wraps
+from Queue import Queue, Full
+
+from flask import g, request
+from trollius import Return
+
+
+logger = logging.getLogger(__name__)
+
+# Buckets for the API response times.
+API_RESPONSE_TIME_BUCKETS = [.01, .025, .05, .1, .25, .5, 1.0, 2.5, 5.0]
+
+# Buckets for the builder start times.
+BUILDER_START_TIME_BUCKETS = [.5, 1.0, 5.0, 10.0, 30.0, 60.0, 120.0, 180.0, 240.0, 300.0, 600.0]
+
+
+class MetricQueue(object):
+  """ Object to which various metrics are written, for distribution to metrics collection
+      system(s) such as Prometheus.
+  """
+  def __init__(self, prom):
+    # Define the various exported metrics.
+    self.resp_time = prom.create_histogram('response_time', 'HTTP response time in seconds',
+                                           labelnames=['endpoint'],
+                                           buckets=API_RESPONSE_TIME_BUCKETS)
+    self.resp_code = prom.create_counter('response_code', 'HTTP response code',
+                                         labelnames=['endpoint', 'code'])
+    self.non_200 = prom.create_counter('response_non200', 'Non-200 HTTP response codes',
+                                       labelnames=['endpoint'])
+    self.error_500 = prom.create_counter('response_500', '5XX HTTP response codes',
+                                         labelnames=['endpoint'])
+    self.multipart_upload_start = prom.create_counter('multipart_upload_start',
+                                                      'Multipart upload started')
+    self.multipart_upload_end = prom.create_counter('multipart_upload_end',
+                                                    'Multipart upload ends.', labelnames=['type'])
+    self.build_capacity_shortage = prom.create_gauge('build_capacity_shortage',
+                                                     'Build capacity shortage.')
+    self.builder_time_to_start = prom.create_histogram('builder_tts',
+                                                       'Time from triggering to starting a builder.',
+                                                       labelnames=['builder_type'],
+                                                       buckets=BUILDER_START_TIME_BUCKETS)
+    self.builder_time_to_build = prom.create_histogram('builder_ttb',
+                                                       'Time from triggering to actually starting a build',
+                                                       labelnames=['builder_type'],
+                                                       buckets=BUILDER_START_TIME_BUCKETS)
+    self.build_time = prom.create_histogram('build_time', 'Time spent building', labelnames=['builder_type'])
+    self.builder_fallback = prom.create_counter('builder_fallback', 'Builder fell back to secondary executor')
+    self.build_start_success = prom.create_counter('build_start_success', 'Executor succeeded in starting a build', labelnames=['builder_type'])
+    self.build_start_failure = prom.create_counter('build_start_failure', 'Executor failed to start a build', labelnames=['builder_type'])
+    self.percent_building = prom.create_gauge('build_percent_building', 'Percent building.')
+    self.build_counter = prom.create_counter('builds', 'Number of builds', labelnames=['name'])
+    self.ephemeral_build_workers = prom.create_counter('ephemeral_build_workers',
+      'Number of started ephemeral build workers')
+    self.ephemeral_build_worker_failure = prom.create_counter('ephemeral_build_worker_failure',
+      'Number of failed-to-start ephemeral build workers')
+
+    self.work_queue_running = prom.create_gauge('work_queue_running', 'Running items in a queue',
+                                                labelnames=['queue_name'])
+    self.work_queue_available = prom.create_gauge('work_queue_available',
+                                                  'Available items in a queue',
+                                                  labelnames=['queue_name'])
+
+    self.work_queue_available_not_running = prom.create_gauge('work_queue_available_not_running',
+                                                              'Available items that are not yet running',
+                                                              labelnames=['queue_name'])
+
+    self.repository_pull = prom.create_counter('repository_pull', 'Repository Pull Count',
+                                               labelnames=['namespace', 'repo_name', 'protocol',
+                                                           'status'])
+
+    self.repository_push = prom.create_counter('repository_push', 'Repository Push Count',
+                                               labelnames=['namespace', 'repo_name', 'protocol',
+                                                           'status'])
+
+    self.repository_build_queued = prom.create_counter('repository_build_queued',
+                                                       'Repository Build Queued Count',
+                                                       labelnames=['namespace', 'repo_name'])
+
+    self.repository_build_completed = prom.create_counter('repository_build_completed',
+                                                          'Repository Build Complete Count',
+                                                          labelnames=['namespace', 'repo_name',
+                                                                      'status', 'executor'])
+
+    self.chunk_size = prom.create_histogram('chunk_size',
+                                            'Registry blob chunk size',
+                                            labelnames=['storage_region'])
+
+    self.chunk_upload_time = prom.create_histogram('chunk_upload_time',
+                                                   'Registry blob chunk upload time',
+                                                   labelnames=['storage_region'])
+
+    self.authentication_count = prom.create_counter('authentication_count',
+                                                    'Authentication count',
+                                                    labelnames=['kind', 'status'])
+
+    self.repository_count = prom.create_gauge('repository_count', 'Number of repositories')
+    self.user_count = prom.create_gauge('user_count', 'Number of users')
+    self.org_count = prom.create_gauge('org_count', 'Number of Organizations')
+    self.robot_count = prom.create_gauge('robot_count', 'Number of robot accounts')
+
+    self.instance_key_renewal_success = prom.create_counter('instance_key_renewal_success',
+                                                            'Instance Key Renewal Success Count',
+                                                            labelnames=['key_id'])
+
+    self.instance_key_renewal_failure = prom.create_counter('instance_key_renewal_failure',
+                                                            'Instance Key Renewal Failure Count',
+                                                            labelnames=['key_id'])
+
+    self.invalid_instance_key_count = prom.create_counter('invalid_registry_instance_key_count',
+                                                          'Invalid registry instance key count',
+                                                          labelnames=['key_id'])
+
+    self.verb_action_passes = prom.create_counter('verb_action_passes', 'Verb Pass Count',
+                                                  labelnames=['kind', 'pass_count'])
+
+    self.push_byte_count = prom.create_counter('registry_push_byte_count',
+                                               'Number of bytes pushed to the registry')
+
+    self.pull_byte_count = prom.create_counter('estimated_registry_pull_byte_count',
+                                               'Number of (estimated) bytes pulled from the registry',
+                                               labelnames=['protocol_version'])
+
+    # Deprecated: Define an in-memory queue for reporting metrics to CloudWatch or another
+    # provider.
+    self._queue = None
+
+  def enable_deprecated(self, maxsize=10000):
+    self._queue = Queue(maxsize)
+
+  def put_deprecated(self, name, value, **kwargs):
+    if self._queue is None:
+      logger.debug('No metric queue %s %s %s', name, value, kwargs)
+      return
+
+    try:
+      kwargs.setdefault('timestamp', datetime.datetime.now())
+      kwargs.setdefault('dimensions', {})
+      self._queue.put_nowait((name, value, kwargs))
+    except Full:
+      logger.error('Metric queue full')
+
+  def get_deprecated(self):
+    return self._queue.get()
+
+  def get_nowait_deprecated(self):
+    return self._queue.get_nowait()
+
+
+def duration_collector_async(metric, labelvalues):
+  """ Decorates a method to have its duration time logged to the metric. """
+  def decorator(func):
+    @wraps(func)
+    def wrapper(*args, **kwargs):
+      trigger_time = time.time()
+      try:
+        rv = func(*args, **kwargs)
+      except Return as e:
+        metric.Observe(time.time() - trigger_time, labelvalues=labelvalues)
+        raise e
+      return rv
+    return wrapper
+  return decorator
+
+
+def time_decorator(name, metric_queue):
+  """ Decorates an endpoint method to have its request time logged to the metrics queue. """
+  after = _time_after_request(name, metric_queue)
+  def decorator(func):
+    @wraps(func)
+    def wrapper(*args, **kwargs):
+      _time_before_request()
+      rv = func(*args, **kwargs)
+      after(rv)
+      return rv
+    return wrapper
+  return decorator
+
+
+def time_blueprint(bp, metric_queue):
+  """ Decorates a blueprint to have its request time logged to the metrics queue. """
+  bp.before_request(_time_before_request)
+  bp.after_request(_time_after_request(bp.name, metric_queue))
+
+
+def _time_before_request():
+  g._request_start_time = time.time()
+
+
+def _time_after_request(name, metric_queue):
+  def f(r):
+    start = getattr(g, '_request_start_time', None)
+    if start is None:
+      return r
+
+    dur = time.time() - start
+
+    metric_queue.resp_time.Observe(dur, labelvalues=[request.endpoint])
+    metric_queue.resp_code.Inc(labelvalues=[request.endpoint, r.status_code])
+
+    if r.status_code >= 500:
+      metric_queue.error_500.Inc(labelvalues=[request.endpoint])
+    elif r.status_code < 200 or r.status_code >= 300:
+      metric_queue.non_200.Inc(labelvalues=[request.endpoint])
+
+    return r
+  return f

util/metrics/prometheus.py

@@ -0,0 +1,168 @@
+import datetime
+import json
+import logging
+
+from Queue import Queue, Full, Empty
+from threading import Thread
+
+import requests
+
+
+logger = logging.getLogger(__name__)
+
+QUEUE_MAX = 1000
+MAX_BATCH_SIZE = 100
+REGISTER_WAIT = datetime.timedelta(hours=1)
+
+class PrometheusPlugin(object):
+  """ Application plugin for reporting metrics to Prometheus. """
+  def __init__(self, app=None):
+    self.app = app
+    if app is not None:
+      self.state = self.init_app(app)
+    else:
+      self.state = None
+
+  def init_app(self, app):
+    prom_url = app.config.get('PROMETHEUS_AGGREGATOR_URL')
+    prom_namespace = app.config.get('PROMETHEUS_NAMESPACE')
+    logger.debug('Initializing prometheus with aggregator url: %s', prom_url)
+    prometheus = Prometheus(prom_url, prom_namespace)
+
+    # register extension with app
+    app.extensions = getattr(app, 'extensions', {})
+    app.extensions['prometheus'] = prometheus
+    return prometheus
+
+  def __getattr__(self, name):
+    return getattr(self.state, name, None)
+
+
+class Prometheus(object):
+  """ Aggregator for collecting stats that are reported to Prometheus. """
+  def __init__(self, url=None, namespace=None):
+    self._metric_collectors = []
+    self._url = url
+    self._namespace = namespace or ''
+
+    if url is not None:
+      self._queue = Queue(QUEUE_MAX)
+      self._sender = _QueueSender(self._queue, url, self._metric_collectors)
+      self._sender.start()
+      logger.debug('Prometheus aggregator sending to %s', url)
+    else:
+      self._queue = None
+      logger.debug('Prometheus aggregator disabled')
+
+  def enqueue(self, call, data):
+    if not self._queue:
+      return
+
+    v = json.dumps({
+      'Call': call,
+      'Data': data,
+    })
+
+    if call == 'register':
+      self._metric_collectors.append(v)
+      return
+
+    try:
+      self._queue.put_nowait(v)
+    except Full:
+      # If the queue is full, it is because 1) no aggregator was enabled or 2)
+      # the aggregator is taking a long time to respond to requests. In the case
+      # of 1, it's probably enterprise mode and we don't care. In the case of 2,
+      # the response timeout error is printed inside the queue handler. In either case,
+      # we don't need to print an error here.
+      pass
+
+  def create_gauge(self, *args, **kwargs):
+    return self._create_collector('Gauge', args, kwargs)
+
+  def create_counter(self, *args, **kwargs):
+    return self._create_collector('Counter', args, kwargs)
+
+  def create_summary(self, *args, **kwargs):
+    return self._create_collector('Summary', args, kwargs)
+
+  def create_histogram(self, *args, **kwargs):
+    return self._create_collector('Histogram', args, kwargs)
+
+  def create_untyped(self, *args, **kwargs):
+    return self._create_collector('Untyped', args, kwargs)
+
+  def _create_collector(self, collector_type, args, kwargs):
+    kwargs['namespace'] = kwargs.get('namespace', self._namespace)
+    return _Collector(self.enqueue, collector_type, *args, **kwargs)
+
+
+class _QueueSender(Thread):
+  """ Helper class which uses a thread to asynchronously send metrics to the local Prometheus
+      aggregator. """
+  def __init__(self, queue, url, metric_collectors):
+    Thread.__init__(self)
+    self.daemon = True
+    self.next_register = datetime.datetime.now()
+    self._queue = queue
+    self._url = url
+    self._metric_collectors = metric_collectors
+
+  def run(self):
+    while True:
+      reqs = []
+      reqs.append(self._queue.get())
+
+      while len(reqs) < MAX_BATCH_SIZE:
+        try:
+          req = self._queue.get_nowait()
+          reqs.append(req)
+        except Empty:
+          break
+
+      try:
+        resp = requests.post(self._url + '/call', '\n'.join(reqs))
+        if resp.status_code == 500 and self.next_register <= datetime.datetime.now():
+          resp = requests.post(self._url + '/call', '\n'.join(self._metric_collectors))
+          self.next_register = datetime.datetime.now() + REGISTER_WAIT
+          logger.debug('Register returned %s for %s metrics; setting next to %s', resp.status_code,
+                       len(self._metric_collectors), self.next_register)
+        elif resp.status_code != 200:
+          logger.debug('Failed sending to prometheus: %s: %s: %s', resp.status_code, resp.text,
+                       ', '.join(reqs))
+        else:
+          logger.debug('Sent %d prometheus metrics', len(reqs))
+      except:
+        logger.exception('Failed to write to prometheus aggregator: %s', reqs)
+
+
+class _Collector(object):
+  """ Collector for a Prometheus metric. """
+  def __init__(self, enqueue_method, collector_type, collector_name, collector_help,
+               namespace='', subsystem='', **kwargs):
+    self._enqueue_method = enqueue_method
+    self._base_args = {
+      'Name': collector_name,
+      'Namespace': namespace,
+      'Subsystem': subsystem,
+      'Type': collector_type,
+    }
+
+    registration_params = dict(kwargs)
+    registration_params.update(self._base_args)
+    registration_params['Help'] = collector_help
+
+    self._enqueue_method('register', registration_params)
+
+  def __getattr__(self, method):
+    def f(value=0, labelvalues=()):
+      data = dict(self._base_args)
+      data.update({
+        'Value': value,
+        'LabelValues': [str(i) for i in labelvalues],
+        'Method': method,
+      })
+
+      self._enqueue_method('put', data)
+
+    return f

util/metrics/test/test_metricqueue.py

@@ -0,0 +1,58 @@
+import time
+
+import pytest
+
+from mock import Mock
+from trollius import coroutine, Return, get_event_loop, From
+
+from util.metrics.metricqueue import duration_collector_async
+
+
+mock_histogram = Mock()
+
+class NonReturn(Exception):
+  pass 
+
+
+@coroutine
+@duration_collector_async(mock_histogram, labelvalues=["testlabel"])
+def duration_decorated():
+  time.sleep(1)
+  raise Return("fin")
+
+
+@coroutine
+@duration_collector_async(mock_histogram, labelvalues=["testlabel"])
+def duration_decorated_error():
+  raise NonReturn("not a Return error")
+
+@coroutine
+def calls_decorated():
+  yield From(duration_decorated())
+
+
+def test_duration_decorator():
+  loop = get_event_loop()
+  loop.run_until_complete(duration_decorated())
+  assert mock_histogram.Observe.called
+  assert 1 - mock_histogram.Observe.call_args[0][0] < 1  # duration should be close to 1s
+  assert mock_histogram.Observe.call_args[1]["labelvalues"] == ["testlabel"]
+
+
+def test_duration_decorator_error():
+  loop = get_event_loop()
+  mock_histogram.reset_mock()
+
+  with pytest.raises(NonReturn):
+    loop.run_until_complete(duration_decorated_error())
+  assert not mock_histogram.Observe.called
+
+
+def test_duration_decorator_caller():
+  mock_histogram.reset_mock()
+
+  loop = get_event_loop()
+  loop.run_until_complete(calls_decorated())
+  assert mock_histogram.Observe.called
+  assert 1 - mock_histogram.Observe.call_args[0][0] < 1  # duration should be close to 1s
+  assert mock_histogram.Observe.call_args[1]["labelvalues"] == ["testlabel"]