buildbucket: add monitoring using ts_mon

appengine/cr-buildbucket/service.py

 # Copyright 2014 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 import datetime
 import json
 import logging
 import urlparse
 from components import auth
 from components import pubsub
 from components import utils
 from google.appengine.api import taskqueue
 from google.appengine.api import modules
 from google.appengine.ext import db
 from google.appengine.ext import deferred
 from google.appengine.ext import ndb
 import acl
 import errors
+import metrics
 import model
 import swarming
 
 MAX_RETURN_BUILDS = 100
 MAX_LEASE_DURATION = datetime.timedelta(hours=2)
 DEFAULT_LEASE_DURATION = datetime.timedelta(minutes=1)
 BUILD_TIMEOUT = datetime.timedelta(days=1)
 
 validate_bucket_name = errors.validate_bucket_name
 
@@ skipping 132 matching lines @@
 
   try:
     yield build.put_async()
   except:  # pragma: no cover
     # Best effort.
     if for_swarming:
       yield swarming.cancel_task_async(build)
     raise
   logging.info(
     'Build %s was created by %s', build.key.id(), identity.to_bytes())
+  metrics.increment(metrics.CREATE_COUNT, build)
 
   if client_operation_id is not None:
     yield ctx.memcache_set(client_operation_cache_key, build.key.id(), 60)
   raise ndb.Return(build)
 
 
 def add(*args, **kwargs):
   """Sync version of add_async."""
   return add_async(*args, **kwargs).get_result()
 
@@ skipping 200 matching lines @@
     build = _get_leasable_build(build_id)
 
     if build.status != model.BuildStatus.SCHEDULED or build.is_leased:
       return False, build
 
     build.lease_expiration_date = lease_expiration_date
     build.regenerate_lease_key()
     build.leasee = auth.get_current_identity()
     build.never_leased = False
     build.put()
+    return True, build
+
+  leased, build = try_lease()
+  if leased:
     logging.info(
       'Build %s was leased by %s', build.key.id(), build.leasee.to_bytes())
-    return True, build
-
-  return try_lease()
+    metrics.increment(metrics.LEASE_COUNT, build)
+  return leased, build
 
 
 def _check_lease(build, lease_key):
   if lease_key != build.lease_key:
     raise errors.LeaseExpiredError(
       'lease_key for build %s is incorrect. Your lease might be expired.' %
       build.key.id())
 
 
 @ndb.transactional
@@ skipping 43 matching lines @@
       build.key.id(),
       build.pubsub_callback.topic,
       build.pubsub_callback.user_data,
       build.pubsub_callback.auth_token,
       _transactional=True,
       _retry_options=taskqueue.TaskRetryOptions(
         task_age_limit=BUILD_TIMEOUT.total_seconds()),
     )
 
 
-@ndb.transactional
 def start(build_id, lease_key, url=None):
   """Marks build as STARTED. Idempotent.
 
   Args:
     build_id: id of the started build.
     lease_key: current lease key.
     url (str): a URL to a build-system-specific build, viewable by a human.
 
   Returns:
     The updated Build.
   """
   validate_lease_key(lease_key)
   validate_url(url)
-  build = _get_leasable_build(build_id)
 
-  if build.status == model.BuildStatus.STARTED:
-    if build.url != url:
-      build.url = url
-      build.put()
+  @ndb.transactional
+  def txn():

[Sergey Berezin, 2015/12/17 00:08:01]

nit: spell out (transaction?)

[nodir, 2015/12/17 01:28:54]

txn is kind of standard, I see it a lot in code by maruel and vadimsh

[Sergey Berezin, 2015/12/17 02:30:18]

Acknowledged.

+    build = _get_leasable_build(build_id)
+
+    if build.status == model.BuildStatus.STARTED:
+      if build.url != url:
+        build.url = url
+        build.put()
+      return build
+    elif build.status == model.BuildStatus.COMPLETED:
+      raise errors.BuildIsCompletedError('Cannot start a completed build')
+    assert build.status == model.BuildStatus.SCHEDULED
+    _check_lease(build, lease_key)
+
+    build.status = model.BuildStatus.STARTED
+    build.status_changed_time = utils.utcnow()
+    build.url = url
+    build.put()
+    _enqueue_callback_task_if_needed(build)
     return build
-  elif build.status == model.BuildStatus.COMPLETED:
-    raise errors.BuildIsCompletedError('Cannot start a completed build')
-  assert build.status == model.BuildStatus.SCHEDULED
-  _check_lease(build, lease_key)
 
-  build.status = model.BuildStatus.STARTED
-  build.status_changed_time = utils.utcnow()
-  build.url = url
-  build.put()
+  build = txn()
   logging.info('Build %s was started. URL: %s', build.key.id(), url)
-  _enqueue_callback_task_if_needed(build)
+  metrics.increment(metrics.START_COUNT, build)
   return build
 
 
-@ndb.transactional_tasklet
+@ndb.tasklet
 def heartbeat_async(build_id, lease_key, lease_expiration_date):
   """Extends build lease.
 
   Args:
     build_id: id of the build.
     lease_key: current lease key.
     lease_expiration_date (datetime.timedelta): new lease expiration date.
 
   Returns:
     The updated Build as Future.
   """
-  try:
+  @ndb.transactional_tasklet
+  def txn():
     validate_lease_key(lease_key)
     if lease_expiration_date is None:
       raise errors.InvalidInputError('Lease expiration date not specified')
     validate_lease_expiration_date(lease_expiration_date)
     build = yield model.Build.get_by_id_async(build_id)
     if build is None:
       raise errors.BuildNotFoundError()
     if build.status == model.BuildStatus.COMPLETED:
       raise errors.BuildIsCompletedError()
     _check_lease(build, lease_key)
     build.lease_expiration_date = lease_expiration_date
     yield build.put_async()
+    raise ndb.Return(build)
+
+  build = None
+  try:
+    build = yield txn()
   except Exception as ex:
     logging.warning('Heartbeat for build %s failed: %s', build_id, ex)
+    metrics.increment(metrics.HEARTBEAT_FAILURE_COUNT, build)

[Sergey Berezin, 2015/12/17 00:08:01]

nit: as an option, you might consider counting all heartbeats, distinguishing
them by a 'status' field ('failed' or 'succeeded'). As a bonus, you'd be able to
track heartbeat failure rate, not just the raw count.

[nodir, 2015/12/17 01:28:54]

hearbeats are sent in batches and heartbeat_async is called many times per
request. Are you sure metrics.increment won't try to persist state to memcache
(synchronously)? Reading gae_ts_mon code [1] it seems it will try to persist it
right away, so I hesitate.

[1]:
https://code.google.com/p/chromium/codesearch#chromium/infra/appengine_module...

[Sergey Berezin, 2015/12/17 02:30:18]

If DeferredMetricStore is not initialized (as is the case for Cloud Endpoints
handler), it may indeed send metrics to memcache synchronously. This will surely
be fixed once we add support for Cloud Endpoints. Meanwhile, I suppose we can
just report failures. But you can still define the metric with a status field,
and add all heartbeats later, assuming my initial comment actually makes sense
for it.

[nodir, 2015/12/17 03:19:56]

Done.

     raise
   raise ndb.Return(build)
 
 
 def heartbeat(build_id, lease_key, lease_expiration_date):
   future = heartbeat_async(build_id, lease_key, lease_expiration_date)
   return future.get_result()
 
 
 def heartbeat_batch(heartbeats):
@@ skipping 12 matching lines @@
     build_id = hb['build_id']
     exc = future.get_exception()
     if not exc:
       return build_id, future.get_result(), None
     else:
       return build_id, None, exc
 
   return [get_result(h, f) for h, f in futures]
 
 
-@ndb.transactional
 def _complete(
     build_id, lease_key, result, result_details, failure_reason=None,
     url=None):
   """Marks a build as completed. Used by succeed and fail methods."""
   validate_lease_key(lease_key)
   validate_url(url)
   assert result in (model.BuildResult.SUCCESS, model.BuildResult.FAILURE)
-  build = _get_leasable_build(build_id)
 
-  if build.status == model.BuildStatus.COMPLETED:
-    if (build.result == result and
-        build.failure_reason == failure_reason and
-        build.result_details == result_details and
-        build.url == url):
-      return build
-    raise errors.BuildIsCompletedError(
-      'Build %s has already completed' % build_id)
-  _check_lease(build, lease_key)
+  @ndb.transactional
+  def txn():
+    build = _get_leasable_build(build_id)
 
-  build.status = model.BuildStatus.COMPLETED
-  build.status_changed_time = utils.utcnow()
-  build.complete_time = utils.utcnow()
-  build.result = result
-  if url is not None:  # pragma: no branch
-    build.url = url
-  build.result_details = result_details
-  build.failure_reason = failure_reason
-  build.clear_lease()
-  build.put()
+    if build.status == model.BuildStatus.COMPLETED:
+      if (build.result == result and
+          build.failure_reason == failure_reason and
+          build.result_details == result_details and
+          build.url == url):
+        return build
+      raise errors.BuildIsCompletedError(
+        'Build %s has already completed' % build_id)
+    _check_lease(build, lease_key)
+
+    build.status = model.BuildStatus.COMPLETED
+    build.status_changed_time = utils.utcnow()
+    build.complete_time = utils.utcnow()
+    build.result = result
+    if url is not None:  # pragma: no branch
+      build.url = url
+    build.result_details = result_details
+    build.failure_reason = failure_reason
+    build.clear_lease()
+    build.put()
+    _enqueue_callback_task_if_needed(build)
+    return build
+
+  build = txn()
   logging.info(
     'Build %s was completed. Status: %s. Result: %s',
     build.key.id(), build.status, build.result)
-  _enqueue_callback_task_if_needed(build)
+  metrics.increment(
+    metrics.COMPLETE_COUNT,
+    build,
+    result=result,
+    failure_reason=failure_reason,
+  )
   return build
 
 
 def succeed(build_id, lease_key, result_details=None, url=None):
   """Marks a build as succeeded. Idempotent.
 
   Args:
     build_id: id of the build to complete.
     lease_key: current lease key.
     result_details (dict): build result description.
@@ skipping 19 matching lines @@
 
   Returns:
     The failed Build.
   """
   failure_reason = failure_reason or model.FailureReason.BUILD_FAILURE
   return _complete(
     build_id, lease_key, model.BuildResult.FAILURE, result_details,
     failure_reason, url=url)
 
 
-@ndb.transactional
 def cancel(build_id):
   """Cancels build. Does not require a lease key.
 
   The current user has to have a permission to cancel a build in the
   bucket.
 
   Returns:
     Canceled Build.
   """
-  build = model.Build.get_by_id(build_id)
-  if build is None:
-    raise errors.BuildNotFoundError()
-  if not acl.can_cancel_build(build):
-    raise current_identity_cannot('cancel build %s', build.key.id())
-  if build.status == model.BuildStatus.COMPLETED:
-    if build.result == model.BuildResult.CANCELED:
-      return build
-    raise errors.BuildIsCompletedError('Cannot cancel a completed build')
-  now = utils.utcnow()
-  build.status = model.BuildStatus.COMPLETED
-  build.status_changed_time = now
-  build.result = model.BuildResult.CANCELED
-  build.cancelation_reason = model.CancelationReason.CANCELED_EXPLICITLY
-  build.complete_time = now
-  build.clear_lease()
-  build.put()
+  @ndb.transactional
+  def txn():
+    build = model.Build.get_by_id(build_id)
+    if build is None:
+      raise errors.BuildNotFoundError()
+    if not acl.can_cancel_build(build):
+      raise current_identity_cannot('cancel build %s', build.key.id())
+    if build.status == model.BuildStatus.COMPLETED:
+      if build.result == model.BuildResult.CANCELED:
+        return build
+      raise errors.BuildIsCompletedError('Cannot cancel a completed build')
+    now = utils.utcnow()
+    build.status = model.BuildStatus.COMPLETED
+    build.status_changed_time = now
+    build.result = model.BuildResult.CANCELED
+    build.cancelation_reason = model.CancelationReason.CANCELED_EXPLICITLY
+    build.complete_time = now
+    build.clear_lease()
+    build.put()
+    return build
+
+  build = txn()
   logging.info(
     'Build %s was cancelled by %s', build.key.id(),
     auth.get_current_identity().to_bytes())
+  metrics.increment(
+    metrics.COMPLETE_COUNT,
+    build,
+    result=build.result,
+    cancelation_reason=build.cancelation_reason,
+  )
   return build
 
 
-@ndb.transactional_tasklet
+@ndb.tasklet
 def _reset_expired_build_async(build_id):
-  build = yield model.Build.get_by_id_async(build_id)
-  if not build or build.lease_expiration_date is None:  # pragma: no cover
-    return
-  is_expired = build.lease_expiration_date <= utils.utcnow()
-  if not is_expired:  # pragma: no cover
-    return
+  @ndb.transactional_tasklet
+  def txn():
+    build = yield model.Build.get_by_id_async(build_id)
+    if not build or build.lease_expiration_date is None:  # pragma: no cover
+      return
+    is_expired = build.lease_expiration_date <= utils.utcnow()
+    if not is_expired:  # pragma: no cover
+      return
 
-  assert build.status != model.BuildStatus.COMPLETED, (
-    'Completed build is leased')
-  build.clear_lease()
-  build.status = model.BuildStatus.SCHEDULED
-  build.status_changed_time = utils.utcnow()
-  build.url = None
-  yield build.put_async()
+    assert build.status != model.BuildStatus.COMPLETED, (
+      'Completed build is leased')
+    build.clear_lease()
+    build.status = model.BuildStatus.SCHEDULED
+    build.status_changed_time = utils.utcnow()
+    build.url = None
+    yield build.put_async()
+    raise ndb.Return(build)
+
+  build = yield txn()
   logging.info('Expired build %s was reset', build_id)
+  metrics.increment(metrics.LEASE_EXPIRATION_COUNT, build)
 
 
 @ndb.transactional_tasklet
 def _timeout_async(build_id):
   build = yield model.Build.get_by_id_async(build_id)
   if not build or build.status == model.BuildStatus.COMPLETED:
     return  # pragma: no cover
 
   build.clear_lease()
   build.status = model.BuildStatus.COMPLETED
@@ skipping 77 matching lines @@
   if isinstance(identity, basestring):
     if not identity:  # pragma: no cover
       return None
     if ':' not in identity:  # pragma: no branch
       identity = 'user:%s' % identity
     try:
       identity = auth.Identity.from_bytes(identity)
     except ValueError as ex:
       raise errors.InvalidInputError('Invalid identity identity: %s' % ex)
   return identity