feat(core): ENG-11826 report failed downloads to the callback

tests/core/test_remote_logging.py

@@ -42,6 +42,45 @@ def serialize(self):
 
         assert captured['payload']['action_meta']['completed'] is expected
 
+    @pytest.mark.asyncio
+    @pytest.mark.parametrize('status_code', [200, 500, None])
+    async def test_download_action_forwards_status_code(self, monkeypatch, status_code):
+        """The status lets the OSF tell a real failure from a user cancelling mid-stream."""
+        captured = {}
+
+        async def fake_send_signed_request(method, url, payload):
+            captured['payload'] = payload
+            return 200, b'success'
+
+        monkeypatch.setattr(remote_logging.utils, 'send_signed_request', fake_send_signed_request)
+
+        class DummySource:
+            auth = {'callback_url': 'https://example.com/callback'}
+
+            def serialize(self):
+                return {'provider': 'osf'}
+
+        source = DummySource()
+        request = {
+            'request': {
+                'method': 'GET',
+                'url': 'https://example.com/file',
+                'headers': {},
+            },
+            'referrer': {'url': None},
+            'tech': {'ua': 'test-agent', 'ip': '127.0.0.1'},
+        }
+
+        await remote_logging.log_to_callback(
+            'download_zip',
+            source=source,
+            request=request,
+            completed=False,
+            status_code=status_code,
+        )
+
+        assert captured['payload']['action_meta']['status_code'] == status_code
+
     @pytest.mark.asyncio
     async def test_non_download_action_omits_completed_flag(self, monkeypatch):
         captured = {}

tests/server/api/v1/test_provider.py

@@ -175,7 +175,8 @@ async def test_on_finish_download_file(self, http_request, download_completed, e
         handler._send_hook = mock.Mock()
 
         assert handler.on_finish() is None
-        handler._send_hook.assert_called_once_with('download_file', completed=expected_completed)
+        handler._send_hook.assert_called_once_with(
+            'download_file', completed=expected_completed, status_code=200)
 
     @pytest.mark.asyncio
     async def test_on_finish_download_zip(self, http_request):
@@ -187,7 +188,87 @@ async def test_on_finish_download_zip(self, http_request):
         handler._send_hook = mock.Mock()
 
         assert handler.on_finish() is None
-        handler._send_hook.assert_called_once_with('download_zip', completed=True)
+        handler._send_hook.assert_called_once_with('download_zip', completed=True, status_code=200)
+
+    @pytest.mark.asyncio
+    @pytest.mark.parametrize('status', [500, 502, 400, 404])
+    async def test_on_finish_failed_download_file(self, http_request, status):
+        """A file download that authorized and started but then errored is reported as
+        failed, so the OSF can count it -- the "attempted but failed" case."""
+        handler = mock_handler(http_request)
+        handler.request.method = 'GET'
+        handler.path = WaterButlerPath('/file')
+        handler._status_code = status
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        handler._send_hook.assert_called_once_with(
+            'download_file', completed=False, status_code=status)
+
+    @pytest.mark.asyncio
+    async def test_on_finish_failed_download_zip(self, http_request):
+        handler = mock_handler(http_request)
+        handler.request.method = 'GET'
+        handler.request.query_arguments['zip'] = ''
+        handler.path = WaterButlerPath('/folder/')
+        handler._status_code = 500
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        handler._send_hook.assert_called_once_with(
+            'download_zip', completed=False, status_code=500)
+
+    @pytest.mark.asyncio
+    async def test_failed_download_not_reported_without_a_provider(self, http_request):
+        """A request that failed during auth never got a provider, so there's no callback
+        url to report to -- it must stay silent, exactly as before."""
+        handler = mock_handler(http_request)
+        handler.request.method = 'GET'
+        handler.path = WaterButlerPath('/file')
+        handler.provider = None
+        handler._status_code = 500
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        assert not handler._send_hook.called
+
+    @pytest.mark.asyncio
+    async def test_failed_download_not_reported_when_path_never_validated(self, http_request):
+        """self.path is still the raw string it starts as -- validation never finished, so
+        the download never really began."""
+        handler = mock_handler(http_request)
+        handler.request.method = 'GET'
+        handler.path = '/test_path'
+        handler._status_code = 500
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        assert not handler._send_hook.called
+
+    @pytest.mark.asyncio
+    @pytest.mark.parametrize('method', ['PUT', 'POST', 'DELETE'])
+    async def test_failed_non_download_is_not_reported(self, http_request, method):
+        """Only downloads are recorded on failure; a failed upload/move/delete stays silent."""
+        handler = mock_handler(http_request)
+        handler.request.method = method
+        handler.path = WaterButlerPath('/file')
+        handler._status_code = 500
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        assert not handler._send_hook.called
+
+    @pytest.mark.asyncio
+    async def test_failed_folder_listing_is_not_reported(self, http_request):
+        """A folder GET without ?zip is a metadata listing, not a download."""
+        handler = mock_handler(http_request)
+        handler.request.method = 'GET'
+        handler.path = WaterButlerPath('/folder/')
+        handler._status_code = 500
+        handler._send_hook = mock.Mock()
+
+        assert handler.on_finish() is None
+        assert not handler._send_hook.called
 
     @pytest.mark.asyncio
     async def test_dont_send_hook_on_file_metadata(self, http_request):
@@ -338,4 +419,4 @@ async def test_logging_direct_partial_download_file(self, http_request):
         handler._send_hook = mock.Mock()
 
         assert handler.on_finish() is None
-        handler._send_hook.assert_called_once_with('download_file', completed=True)
+        handler._send_hook.assert_called_once_with('download_file', completed=True, status_code=302)

waterbutler/core/remote_logging.py

@@ -22,7 +22,7 @@
 
 @utils.async_retry(retries=5, backoff=5)
 async def log_to_callback(action, source=None, destination=None, start_time=None, errors=None,
-                          request=None, bytes_downloaded=0, completed=False):
+                          request=None, bytes_downloaded=0, completed=False, status_code=None):
     """PUT a logging payload back to the callback given by the auth provider."""
     errors = errors or []
     request = request or {}
@@ -64,6 +64,9 @@ async def log_to_callback(action, source=None, destination=None, start_time=None
                          settings.MFR_IDENTIFYING_HEADER in request["request"]["headers"])
         log_payload['action_meta']['is_mfr_render'] = is_mfr_render
         log_payload['action_meta']['completed'] = completed
+        # The HTTP status lets the OSF tell a genuine failure (5xx) apart from a user
+        # cancelling mid-stream (200, headers already sent) -- both arrive as completed=False.
+        log_payload['action_meta']['status_code'] = status_code
         log_payload['action_meta'].update(_download_link_tags(request))
 
     log_payload['action_meta']['bytes_downloaded'] = bytes_downloaded
@@ -226,13 +229,14 @@ async def _send_to_keen(payload, collection, project_id, write_key, action, doma
 
 def log_file_action(action, source, api_version, destination=None, request=None,
                     start_time=None, errors=None, bytes_downloaded=None, bytes_uploaded=None,
-                    completed=False):
+                    completed=False, status_code=None):
     """Kick off logging actions in the background. Returns array of asyncio.Tasks."""
     request = request or {}
     return [
         log_to_callback(action, source=source, destination=destination,
                         start_time=start_time, errors=errors, request=request,
-                        bytes_downloaded=bytes_downloaded, completed=completed,),
+                        bytes_downloaded=bytes_downloaded, completed=completed,
+                        status_code=status_code,),
         asyncio.ensure_future(
             log_to_keen(action, source=source, destination=destination,
                         errors=errors, request=request, api_version=api_version,

waterbutler/server/api/v1/provider/__init__.py

@@ -216,16 +216,20 @@ async def prepare_stream(self):
     def on_finish(self):
         status, method = self.get_status(), self.request.method.upper()
 
-        # If the response code is not within the 200-302 range, the request was a HEAD or OPTIONS,
-        # the response code is 202, or the response was a 206 partial request, then no callbacks
-        # should be sent and no metrics collected.  For 202s, celery will send its own callback.
-        # Osfstorage and s3 can return 302s for file downloads, which should be tallied.
-        if any({
-            method in {'HEAD', 'OPTIONS'},
-            status in {202, 206},
-            status > 302,
-            status < 200
-        }):
+        # HEAD/OPTIONS carry no body, 202 means celery will send its own callback, and 206 is a
+        # partial range request -- none of these should produce a callback.
+        if method in {'HEAD', 'OPTIONS'} or status in {202, 206}:
+            return
+
+        # A download that got far enough to authorize and start but then errored is worth
+        # recording -- it's the "attempted but failed through no fault of the user" case the OSF
+        # wants counted.  Everything else that errors (a failed upload, move, delete, or a request
+        # rejected during auth/validation) is left alone, exactly as before.  See
+        # _is_reportable_download_failure for why the guard is what it is.
+        if status < 200 or status > 302:
+            if self._is_reportable_download_failure(method):
+                action = 'download_file' if self.path.is_file else 'download_zip'
+                self._send_hook(action, completed=False, status_code=status)
             return
 
         # WB doesn't send along Range headers when requesting signed urls, expecting the client
@@ -257,12 +261,38 @@ def on_finish(self):
 
         if action in {'download_file', 'download_zip'}:
             completed = getattr(self, '_download_completed', status in {200, 302})
-            self._send_hook(action, completed=completed)
+            self._send_hook(action, completed=completed, status_code=status)
             return
 
         self._send_hook(action)
 
-    def _send_hook(self, action, completed=False):
+    def _is_reportable_download_failure(self, method):
+        """Whether a non-success response is a download we can and should report as failed.
+
+        We can only report a failure if auth got far enough to give us a provider -- and
+        therefore a callback url -- and the path validated into a real WaterButlerPath.  A
+        request that failed during auth or path validation never legitimately started and has
+        nowhere to report to, so it's left alone (same as before this change).  Uploads, moves
+        and deletes are out of scope; only GET downloads are recorded.
+        """
+        if method != 'GET':
+            return False
+        # provider is only set once auth has succeeded; without it there's no callback url.
+        if getattr(self, 'provider', None) is None:
+            return False
+        # self.path starts life as a raw string and only becomes a WaterButlerPath (with
+        # is_file/is_folder) once validate_v1_path completes.  A raw string means validation
+        # never finished, so the download was rejected before it began.
+        if not hasattr(self.path, 'is_file'):
+            return False
+        # metadata / revision listings and un-zipped folder listings aren't downloads.
+        if 'meta' in self.request.query_arguments or 'revisions' in self.request.query_arguments:
+            return False
+        if self.path.is_folder and 'zip' not in self.request.query_arguments:
+            return False
+        return True
+
+    def _send_hook(self, action, completed=False, status_code=None):
         source = None
         destination = None
 
@@ -288,4 +318,4 @@ def _send_hook(self, action, completed=False):
                                        request=remote_logging._serialize_request(self.request),
                                        bytes_downloaded=self.bytes_downloaded,
                                        bytes_uploaded=self.bytes_uploaded,
-                                       completed=completed)
+                                       completed=completed, status_code=status_code)