diff --git a/tests/core/test_remote_logging.py b/tests/core/test_remote_logging.py index f9fde0a02..3c9af71c8 100644 --- a/tests/core/test_remote_logging.py +++ b/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 = {} diff --git a/tests/server/api/v1/test_provider.py b/tests/server/api/v1/test_provider.py index e794ae7c0..5f895f24b 100644 --- a/tests/server/api/v1/test_provider.py +++ b/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) diff --git a/waterbutler/core/remote_logging.py b/waterbutler/core/remote_logging.py index ad73eec15..7516a0722 100644 --- a/waterbutler/core/remote_logging.py +++ b/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, diff --git a/waterbutler/server/api/v1/provider/__init__.py b/waterbutler/server/api/v1/provider/__init__.py index a0defc6fe..575b28a31 100644 --- a/waterbutler/server/api/v1/provider/__init__.py +++ b/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)