[ENG-11735] | record download events

addons/base/views.py

@@ -52,9 +52,11 @@
     DraftRegistration,
     Guid,
     FileVersionUserMetadata,
-    FileVersion, NotificationTypeEnum
+    FileVersion, NotificationTypeEnum,
+    DownloadEvent,
 )
 from osf.utils import permissions
+from osf.utils.download_telemetry import never_breaks_downloads, record_download
 from osf.external.gravy_valet import request_helpers
 from website.profile.utils import get_profile_image_url
 from website.project import decorators
@@ -181,6 +183,71 @@ def _download_is_from_mfr(waterbutler_data):
     )
 
 
+def _download_request_is_from_mfr(query_params):
+    """Same question as :func:`_download_is_from_mfr`, asked of a browser request.
+
+    Here the render mode is a query param on the request itself rather than something
+    WaterButler reported to us.
+    """
+    return bool(
+        request.headers.get('X-Cos-Mfr-Render-Request', None) or
+        query_params.get('mode') == 'render'
+    )
+
+
+@never_breaks_downloads
+def _record_file_download(target, file_node, query_params, auth, version=None):
+    """Record a single-file download from the redirect view.
+
+    Only identifiers are handed over — the size, region and materialized path are looked
+    up in the celery task so the download itself doesn't pay for them.
+    """
+    if _download_request_is_from_mfr(query_params):
+        return
+
+    record_download(
+        download_type=DownloadEvent.FILE,
+        resource_guid=getattr(target, '_id', '') or '',
+        file_id=getattr(file_node, '_id', None),
+        version_identifier=getattr(version, 'identifier', None),
+        user_guid=getattr(getattr(auth, 'user', None), '_id', None),
+        ip=request.remote_addr,
+        source_area=query_params.get('source', ''),
+        tz=query_params.get('tz', ''),
+    )
+
+
+@never_breaks_downloads
+def _record_zip_download(payload):
+    """Record a folder or project zip from the WaterButler callback.
+
+    Zips are requested straight from WaterButler, so this callback is the only point at
+    which we hear about them.  The user's IP and the ``source``/``tz`` link tags are
+    forwarded to us in ``action_meta``.
+    """
+    metadata = payload.get('metadata') or {}
+    action_meta = payload.get('action_meta') or {}
+
+    if action_meta.get('is_mfr_render'):
+        return
+
+    materialized = metadata.get('materialized') or metadata.get('path') or ''
+    # The provider root is the whole project; anything below it is one folder.
+    is_whole_project = not materialized.strip('/')
+
+    record_download(
+        download_type=DownloadEvent.PROJECT if is_whole_project else DownloadEvent.FOLDER_ZIP,
+        resource_guid=metadata.get('nid') or '',
+        path=materialized,
+        size_bytes=action_meta.get('bytes_downloaded'),
+        zip_completed=action_meta.get('completed'),
+        user_guid=(payload.get('auth') or {}).get('id'),
+        ip=action_meta.get('ip'),
+        source_area=action_meta.get('source', ''),
+        tz=action_meta.get('tz', ''),
+    )
+
+
 def make_auth(user):
     if user is not None:
         return {
@@ -483,11 +550,11 @@ def create_waterbutler_log(payload, **kwargs):
     with transaction.atomic():
         try:
             auth = payload['auth']
-            # Don't log download actions
+            # Downloads produce no NodeLog, but zips are recorded for telemetry here —
+            # they never pass through the redirect view where single files are caught.
             if payload['action'] in DOWNLOAD_ACTIONS:
-                guid_id = payload['metadata'].get('nid')
-
-                node, _ = Guid.load_referent(guid_id)
+                if payload['action'] == 'download_zip':
+                    _record_zip_download(payload)
                 return {'status': 'success'}
 
             user = OSFUser.load(auth['id'])
@@ -983,6 +1050,7 @@ def addon_view_or_download_file(auth, path, provider, **kwargs):
         }))
 
     if action == 'download':
+        _record_file_download(target, file_node, extras, auth, version=version)
         format = extras.get('format')
         _, extension = os.path.splitext(file_node.name)
         # avoid rendering files with the same format type.
@@ -1045,6 +1113,8 @@ def persistent_file_download(auth, **kwargs):
 
     query_params = request.args.to_dict()
 
+    _record_file_download(file.target, file, query_params, auth)
+
     return make_response(
         '', http_status.HTTP_302_FOUND, {
             'Location': file.generate_waterbutler_url(**query_params),

osf/migrations/0045_downloadevent.py

@@ -12,6 +12,7 @@
     'bgeiger@cos.io',
     'osmand@cos.io',
     'ramya@cos.io',
+    'eric@cos.io',
 ]
 
 

osf/utils/download_telemetry.py

@@ -0,0 +1,166 @@
+import functools
+import logging
+
+from addons.osfstorage.settings import DEFAULT_REGION_NAME
+from framework.celery_tasks import app
+from framework.postcommit_tasks.handlers import enqueue_postcommit_task
+
+logger = logging.getLogger(__name__)
+
+# Set on every user until they pick something in their profile, so it says nothing
+# about where they actually are.
+UNSET_USER_TIMEZONE = 'Etc/UTC'
+
+# Identifiers worth having in the log line to track a failure back to one download.
+# Deliberately excludes the IP.
+LOGGED_CONTEXT_KEYS = ('download_type', 'resource_guid', 'file_id', 'user_guid')
+
+
+def never_breaks_downloads(fn):
+    """Swallow and log anything this raises.
+
+    Wraps the whole capture, not just the write — gathering the values is as capable of
+    raising as storing them is, and neither is a reason for a download to fail.
+    """
+    @functools.wraps(fn)
+    def wrapped(*args, **kwargs):
+        try:
+            return fn(*args, **kwargs)
+        except Exception as exc:
+            # exc_info carries the traceback; the rest names the failure and which
+            # download it was, so a report is actionable without reproducing it.
+            logger.exception(
+                'Failed to record a download event in %s: %s: %s [%s]',
+                fn.__name__,
+                type(exc).__name__,
+                exc,
+                ', '.join(
+                    f'{key}={kwargs[key]!r}'
+                    for key in LOGGED_CONTEXT_KEYS
+                    if kwargs.get(key)
+                ) or 'no context',
+            )
+    return wrapped
+
+
+@never_breaks_downloads
+def record_download(**kwargs):
+    """Enqueue a :class:`DownloadEvent` write."""
+    enqueue_postcommit_task(write_download_event, (), kwargs, celery=True)
+
+
+@app.task(max_retries=5, default_retry_delay=60)
+def write_download_event(
+    download_type,
+    resource_guid='',
+    path='',
+    file_id=None,
+    version_identifier=None,
+    size_bytes=None,
+    storage_region_id=None,
+    zip_completed=None,
+    user_guid=None,
+    ip=None,
+    source_area='',
+    tz='',
+):
+    """Resolve the expensive bits and write one row.
+
+    Callers hand over identifiers rather than loaded objects so that the download request
+    itself does no extra queries — everything that needs a lookup is resolved here.
+    """
+    from osf.models import BaseFileNode, DownloadEvent, OSFUser
+
+    user = OSFUser.load(user_guid) if user_guid else None
+    file_node = BaseFileNode.load(file_id) if file_id else None
+    file_version = _load_file_version(file_node, version_identifier)
+
+    if file_version is not None:
+        if size_bytes is None:
+            size_bytes = file_version.size
+        if storage_region_id is None:
+            storage_region_id = file_version.region_id
+
+    storage_region = _region_name(storage_region_id) or _resource_region_name(resource_guid)
+
+    if not path and file_node is not None:
+        path = getattr(file_node, 'materialized_path', '') or ''
+
+    DownloadEvent.objects.create(
+        download_type=download_type,
+        resource_guid=_truncate(resource_guid, 255),
+        path=path or '',
+        size_bytes=size_bytes if size_bytes is not None and size_bytes >= 0 else None,
+        zip_completed=zip_completed,
+        storage_region=_truncate(storage_region, 64),
+        user_region=_truncate(derive_user_region(tz, user, storage_region), 64),
+        ip=ip or None,
+        source_area=_truncate(source_area, 128),
+        user=user,
+    )
+
+
+def derive_user_region(tz, user, storage_region):
+    """Best available guess at where the user is, most to least trustworthy.
+
+    The live browser timezone is the only real signal; the rest are fallbacks so the
+    dashboard isn't mostly blank.  An empty string means we genuinely don't know, which
+    is more useful than a wrong guess.
+    """
+    if tz:
+        return tz
+
+    profile_timezone = getattr(user, 'timezone', '')
+    if profile_timezone and profile_timezone != UNSET_USER_TIMEZONE:
+        return profile_timezone
+
+    # Everything defaults to the US region, so it only tells us something when it's been
+    # deliberately changed.
+    if storage_region and storage_region != DEFAULT_REGION_NAME:
+        return storage_region
+
+    return ''
+
+
+def _load_file_version(file_node, version_identifier):
+    """The version that was served, for its size and region."""
+    if file_node is None:
+        return None
+
+    from osf.models import FileVersion
+
+    versions = FileVersion.objects.filter(basefilenode=file_node)
+    if version_identifier:
+        return versions.filter(identifier=version_identifier).first()
+    return versions.order_by('-created').first()
+
+
+def _region_name(region_id):
+    if not region_id:
+        return ''
+
+    from addons.osfstorage.models import Region
+
+    region = Region.objects.filter(id=region_id).first()
+    return region.name if region else ''
+
+
+def _resource_region_name(resource_guid):
+    """Where a zip was served from — zips have no single file version to read it off."""
+    if not resource_guid:
+        return ''
+
+    from osf.models import Guid
+
+    resource, _ = Guid.load_referent(resource_guid)
+    region = getattr(resource, 'osfstorage_region', None)
+    return getattr(region, 'name', '') or ''
+
+
+def _truncate(value, max_length):
+    """Keep user-controllable values inside their column.
+
+    ``source`` and ``tz`` arrive off the query string, so they're whatever the caller
+    put there.
+    """
+    return (value or '')[:max_length]