From 914fcacac0301e4acca9433661affb0b5c73bec1 Mon Sep 17 00:00:00 2001 From: Ihor Sokhan Date: Thu, 16 Jul 2026 19:39:33 +0300 Subject: [PATCH 1/5] pass downloaded bytes, IP and completed flag to callback --- tests/core/test_remote_logging.py | 71 +++++++++++++++++++ waterbutler/core/remote_logging.py | 11 ++- waterbutler/server/api/v0/core.py | 10 +-- waterbutler/server/api/v0/crud.py | 4 +- waterbutler/server/api/v0/zip.py | 2 +- .../server/api/v1/provider/__init__.py | 11 ++- 6 files changed, 96 insertions(+), 13 deletions(-) diff --git a/tests/core/test_remote_logging.py b/tests/core/test_remote_logging.py index 88ca8bd428..cdfb55fad4 100644 --- a/tests/core/test_remote_logging.py +++ b/tests/core/test_remote_logging.py @@ -3,6 +3,77 @@ from waterbutler.core import remote_logging +class TestLogToCallback: + + @pytest.mark.asyncio + @pytest.mark.parametrize('completed, expected', [(False, False), (True, True)]) + async def test_download_action_sets_completed_flag(self, monkeypatch, completed, expected): + 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_file', + source=source, + request=request, + completed=completed, + ) + + assert captured['payload']['action_meta']['completed'] is expected + + @pytest.mark.asyncio + async def test_non_download_action_omits_completed_flag(self, monkeypatch): + 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('create', source=source, request=request) + + assert 'completed' not in captured['payload']['action_meta'] + + class TestScrubPayloadForKeen: def test_flat_dict(self): diff --git a/waterbutler/core/remote_logging.py b/waterbutler/core/remote_logging.py index bc2d256cfc..9debe58c47 100644 --- a/waterbutler/core/remote_logging.py +++ b/waterbutler/core/remote_logging.py @@ -18,7 +18,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): + request=None, bytes_downloaded=0, completed=False): """PUT a logging payload back to the callback given by the auth provider.""" errors = errors or [] request = request or {} @@ -59,7 +59,10 @@ async def log_to_callback(action, source=None, destination=None, start_time=None is_mfr_render = (ref_url_domain == settings.MFR_DOMAIN or settings.MFR_IDENTIFYING_HEADER in request["request"]["headers"]) log_payload['action_meta']['is_mfr_render'] = is_mfr_render + log_payload['action_meta']['completed'] = completed + log_payload['action_meta']['bytes_downloaded'] = bytes_downloaded + log_payload['action_meta']['ip'] = request['tech']['ip'] resp_status, resp_data = await utils.send_signed_request('PUT', auth['callback_url'], log_payload) if resp_status // 100 != 2: @@ -217,12 +220,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): + start_time=None, errors=None, bytes_downloaded=None, bytes_uploaded=None, + completed=False): """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,), + start_time=start_time, errors=errors, request=request, + bytes_downloaded=bytes_downloaded, completed=completed,), 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/v0/core.py b/waterbutler/server/api/v0/core.py index 543d966a26..af702e1867 100644 --- a/waterbutler/server/api/v0/core.py +++ b/waterbutler/server/api/v0/core.py @@ -94,12 +94,13 @@ async def prepare(self): self.path = await self.provider.validate_path(**self.arguments) self.arguments['path'] = self.path # TODO Not this - def _send_hook(self, action, metadata=None, path=None): + def _send_hook(self, action, metadata=None, path=None, completed=False): source = LogPayload(self.arguments['nid'], self.provider, metadata=metadata, path=path) remote_logging.log_file_action(action, source=source, api_version='v0', request=remote_logging._serialize_request(self.request), bytes_downloaded=self.bytes_downloaded, - bytes_uploaded=self.bytes_uploaded) + bytes_uploaded=self.bytes_uploaded, + completed=completed) class BaseCrossProviderHandler(BaseHandler): @@ -140,7 +141,7 @@ def json(self): return self._json - def _send_hook(self, action, metadata): + def _send_hook(self, action, metadata, completed=False): source = LogPayload(self.json['source']['nid'], self.source_provider, path=self.json['source']['path']) destination = LogPayload(self.json['destination']['nid'], self.destination_provider, @@ -148,4 +149,5 @@ def _send_hook(self, action, metadata): remote_logging.log_file_action(action, source=source, destination=destination, api_version='v0', request=remote_logging._serialize_request(self.request), bytes_downloaded=self.bytes_downloaded, - bytes_uploaded=self.bytes_uploaded) + bytes_uploaded=self.bytes_uploaded, + completed=completed) diff --git a/waterbutler/server/api/v0/crud.py b/waterbutler/server/api/v0/crud.py index 07034155fa..e7271faecb 100644 --- a/waterbutler/server/api/v0/crud.py +++ b/waterbutler/server/api/v0/crud.py @@ -61,7 +61,7 @@ async def get(self): if isinstance(result, str): self.redirect(result) - self._send_hook('download_file', path=self.path) + self._send_hook('download_file', path=self.path, completed=True) return if getattr(result, 'partial', None): @@ -87,7 +87,7 @@ async def get(self): self.set_header('Content-Type', mime_types[ext]) await self.write_stream(result) - self._send_hook('download_file', path=self.path) + self._send_hook('download_file', path=self.path, completed=True) async def post(self): """Create a folder""" diff --git a/waterbutler/server/api/v0/zip.py b/waterbutler/server/api/v0/zip.py index 2ed0695c65..b52fe1f24f 100644 --- a/waterbutler/server/api/v0/zip.py +++ b/waterbutler/server/api/v0/zip.py @@ -21,4 +21,4 @@ async def get(self): result = await self.provider.zip(**self.arguments) await self.write_stream(result) - self._send_hook('download_zip', path=self.path) + self._send_hook('download_zip', path=self.path, completed=True) diff --git a/waterbutler/server/api/v1/provider/__init__.py b/waterbutler/server/api/v1/provider/__init__.py index 3cf8ed3184..10d85f2ace 100644 --- a/waterbutler/server/api/v1/provider/__init__.py +++ b/waterbutler/server/api/v1/provider/__init__.py @@ -246,6 +246,7 @@ def on_finish(self): 'zip' not in self.request.query_arguments))): return + completed = False # Done here just because method is defined action = { 'GET': lambda: 'download_file' if self.path.is_file else 'download_zip', @@ -254,9 +255,12 @@ def on_finish(self): 'DELETE': lambda: 'delete' }[method]() - self._send_hook(action) + if action in {'download_file', 'download_zip'}: + completed = status in {200, 302} - def _send_hook(self, action): + self._send_hook(action, completed=completed) + + def _send_hook(self, action, completed=False): source = None destination = None @@ -281,4 +285,5 @@ def _send_hook(self, action): remote_logging.log_file_action(action, source=source, destination=destination, api_version='v1', request=remote_logging._serialize_request(self.request), bytes_downloaded=self.bytes_downloaded, - bytes_uploaded=self.bytes_uploaded,) + bytes_uploaded=self.bytes_uploaded, + completed=completed) From f12ad8f813de4a60237ea160db4c508c49cb3b51 Mon Sep 17 00:00:00 2001 From: Ihor Sokhan Date: Fri, 17 Jul 2026 17:47:22 +0300 Subject: [PATCH 2/5] make completed depend on download state --- tests/server/api/v1/test_metadata_mixin.py | 14 ++++++++++++++ tests/server/api/v1/test_provider.py | 6 ++++-- waterbutler/server/api/v0/crud.py | 4 ++-- waterbutler/server/api/v0/zip.py | 4 ++-- waterbutler/server/api/v1/provider/__init__.py | 6 ++++-- waterbutler/server/api/v1/provider/metadata.py | 5 +++-- waterbutler/server/utils.py | 5 +++-- 7 files changed, 32 insertions(+), 12 deletions(-) diff --git a/tests/server/api/v1/test_metadata_mixin.py b/tests/server/api/v1/test_metadata_mixin.py index 48308e806e..09aafabb1d 100644 --- a/tests/server/api/v1/test_metadata_mixin.py +++ b/tests/server/api/v1/test_metadata_mixin.py @@ -120,6 +120,20 @@ async def test_download_file_headers_no_stream_name(self, http_request, mock_str handler.write_stream.assert_awaited_once() + @pytest.mark.asyncio + @pytest.mark.parametrize('write_stream_result, expected_completed', [(True, True), (False, False)]) + async def test_download_file_records_stream_completion(self, http_request, mock_stream, + write_stream_result, expected_completed): + + handler = mock_handler(http_request) + handler.provider.download = MockCoroutine(return_value=mock_stream) + handler.path = WaterButlerPath('/test_file') + handler.write_stream = MockCoroutine(return_value=write_stream_result) + + await handler.download_file() + + assert handler._download_completed is expected_completed + @pytest.mark.asyncio @pytest.mark.parametrize("given_arg,expected_name,filtered_name", [ (['résumé.doc'], 'r%C3%A9sum%C3%A9.doc', 'resume.doc'), diff --git a/tests/server/api/v1/test_provider.py b/tests/server/api/v1/test_provider.py index a39eb9911f..e9445635dc 100644 --- a/tests/server/api/v1/test_provider.py +++ b/tests/server/api/v1/test_provider.py @@ -165,15 +165,17 @@ async def test_data_received_stream(self, http_request): class TestProviderHandlerFinish: @pytest.mark.asyncio - async def test_on_finish_download_file(self, http_request): + @pytest.mark.parametrize('download_completed, expected_completed', [(True, True), (False, False)]) + async def test_on_finish_download_file(self, http_request, download_completed, expected_completed): handler = mock_handler(http_request) handler.request.method = 'GET' handler.path = WaterButlerPath('/file') + handler._download_completed = download_completed handler._send_hook = mock.Mock() assert handler.on_finish() is None - handler._send_hook.assert_called_once_with('download_file') + handler._send_hook.assert_called_once_with('download_file', completed=expected_completed) @pytest.mark.asyncio async def test_on_finish_download_zip(self, http_request): diff --git a/waterbutler/server/api/v0/crud.py b/waterbutler/server/api/v0/crud.py index e7271faecb..0957d00426 100644 --- a/waterbutler/server/api/v0/crud.py +++ b/waterbutler/server/api/v0/crud.py @@ -86,8 +86,8 @@ async def get(self): if ext in mime_types: self.set_header('Content-Type', mime_types[ext]) - await self.write_stream(result) - self._send_hook('download_file', path=self.path, completed=True) + completed = await self.write_stream(result) + self._send_hook('download_file', path=self.path, completed=completed) async def post(self): """Create a folder""" diff --git a/waterbutler/server/api/v0/zip.py b/waterbutler/server/api/v0/zip.py index b52fe1f24f..34c64a7447 100644 --- a/waterbutler/server/api/v0/zip.py +++ b/waterbutler/server/api/v0/zip.py @@ -20,5 +20,5 @@ async def get(self): result = await self.provider.zip(**self.arguments) - await self.write_stream(result) - self._send_hook('download_zip', path=self.path, completed=True) + completed = await self.write_stream(result) + self._send_hook('download_zip', path=self.path, completed=completed) diff --git a/waterbutler/server/api/v1/provider/__init__.py b/waterbutler/server/api/v1/provider/__init__.py index 10d85f2ace..a0defc6fee 100644 --- a/waterbutler/server/api/v1/provider/__init__.py +++ b/waterbutler/server/api/v1/provider/__init__.py @@ -256,9 +256,11 @@ def on_finish(self): }[method]() if action in {'download_file', 'download_zip'}: - completed = status in {200, 302} + completed = getattr(self, '_download_completed', status in {200, 302}) + self._send_hook(action, completed=completed) + return - self._send_hook(action, completed=completed) + self._send_hook(action) def _send_hook(self, action, completed=False): source = None diff --git a/waterbutler/server/api/v1/provider/metadata.py b/waterbutler/server/api/v1/provider/metadata.py index add78e150a..988a91f66a 100644 --- a/waterbutler/server/api/v1/provider/metadata.py +++ b/waterbutler/server/api/v1/provider/metadata.py @@ -73,6 +73,7 @@ async def download_file(self): ) if isinstance(stream, str): + self._download_completed = True return self.redirect(stream) if getattr(stream, 'partial', None): @@ -103,7 +104,7 @@ async def download_file(self): if ext in mime_types: self.set_header('Content-Type', mime_types[ext]) - await self.write_stream(stream) + self._download_completed = await self.write_stream(stream) if getattr(stream, 'partial', False) and isinstance(stream, ResponseStreamReader): await stream.response.release() @@ -133,4 +134,4 @@ async def download_folder_as_zip(self): result = await self.provider.zip(self.path) - await self.write_stream(result) + self._download_completed = await self.write_stream(result) diff --git a/waterbutler/server/utils.py b/waterbutler/server/utils.py index 83d2a01a29..e9afd243eb 100644 --- a/waterbutler/server/utils.py +++ b/waterbutler/server/utils.py @@ -123,7 +123,6 @@ def set_status(self, code, reason=None): async def write_stream(self, stream): try: - while True: chunk = await stream.read(settings.CHUNK_SIZE) if not chunk: @@ -138,4 +137,6 @@ async def write_stream(self, stream): except tornado.iostream.StreamClosedError: # Client has disconnected early. # No need for any exception to be raised - return + return False + + return True From afe36c4954199cba33c45e18cdde29456aaa7a07 Mon Sep 17 00:00:00 2001 From: Ihor Sokhan Date: Mon, 20 Jul 2026 14:38:05 +0300 Subject: [PATCH 3/5] fixed callback for copy action --- tests/server/api/v1/test_provider.py | 4 ++-- waterbutler/core/remote_logging.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/server/api/v1/test_provider.py b/tests/server/api/v1/test_provider.py index e9445635dc..e794ae7c0a 100644 --- a/tests/server/api/v1/test_provider.py +++ b/tests/server/api/v1/test_provider.py @@ -187,7 +187,7 @@ 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') + handler._send_hook.assert_called_once_with('download_zip', completed=True) @pytest.mark.asyncio async def test_dont_send_hook_on_file_metadata(self, http_request): @@ -338,4 +338,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') + handler._send_hook.assert_called_once_with('download_file', completed=True) diff --git a/waterbutler/core/remote_logging.py b/waterbutler/core/remote_logging.py index 9debe58c47..76a478c781 100644 --- a/waterbutler/core/remote_logging.py +++ b/waterbutler/core/remote_logging.py @@ -62,7 +62,7 @@ async def log_to_callback(action, source=None, destination=None, start_time=None log_payload['action_meta']['completed'] = completed log_payload['action_meta']['bytes_downloaded'] = bytes_downloaded - log_payload['action_meta']['ip'] = request['tech']['ip'] + log_payload['action_meta']['ip'] = request.get('tech', {}).get('ip') resp_status, resp_data = await utils.send_signed_request('PUT', auth['callback_url'], log_payload) if resp_status // 100 != 2: From 6505b30d4e49b0a831be7fa9ed5faa33960dd9e8 Mon Sep 17 00:00:00 2001 From: Andriy Sheredko Date: Thu, 23 Jul 2026 16:47:35 +0300 Subject: [PATCH 4/5] feat(wb): ENG-11737 forward download link source and tz to the callback --- tests/core/test_remote_logging.py | 97 ++++++++++++++++++++++++++++++ waterbutler/core/remote_logging.py | 26 ++++++++ 2 files changed, 123 insertions(+) diff --git a/tests/core/test_remote_logging.py b/tests/core/test_remote_logging.py index cdfb55fad4..f9fde0a02b 100644 --- a/tests/core/test_remote_logging.py +++ b/tests/core/test_remote_logging.py @@ -73,6 +73,103 @@ def serialize(self): assert 'completed' not in captured['payload']['action_meta'] + @pytest.mark.asyncio + async def test_download_action_forwards_link_tags(self, monkeypatch): + 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/folder?zip=&source=files&tz=Europe%2FKyiv', + '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) + + assert captured['payload']['action_meta']['source'] == 'files' + assert captured['payload']['action_meta']['tz'] == 'Europe/Kyiv' + + @pytest.mark.asyncio + async def test_download_action_omits_absent_link_tags(self, monkeypatch): + 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_file', source=source, request=request) + + assert 'source' not in captured['payload']['action_meta'] + assert 'tz' not in captured['payload']['action_meta'] + + @pytest.mark.asyncio + async def test_download_link_tags_are_length_capped(self, monkeypatch): + 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() + oversized = 'f' * (remote_logging.MAX_DOWNLOAD_TAG_LENGTH + 50) + request = { + 'request': { + 'method': 'GET', + 'url': f'https://example.com/file?source={oversized}', + 'headers': {}, + }, + 'referrer': {'url': None}, + 'tech': {'ua': 'test-agent', 'ip': '127.0.0.1'}, + } + + await remote_logging.log_to_callback('download_file', source=source, request=request) + + assert len(captured['payload']['action_meta']['source']) == \ + remote_logging.MAX_DOWNLOAD_TAG_LENGTH + class TestScrubPayloadForKeen: diff --git a/waterbutler/core/remote_logging.py b/waterbutler/core/remote_logging.py index 76a478c781..ad73eec15a 100644 --- a/waterbutler/core/remote_logging.py +++ b/waterbutler/core/remote_logging.py @@ -15,6 +15,10 @@ logger = logging.getLogger(__name__) +# Upper bound on the download link tags forwarded to the OSF. They come off the query +# string, so they're user-controllable; the OSF validates them against its own storage. +MAX_DOWNLOAD_TAG_LENGTH = 256 + @utils.async_retry(retries=5, backoff=5) async def log_to_callback(action, source=None, destination=None, start_time=None, errors=None, @@ -60,6 +64,7 @@ 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 + log_payload['action_meta'].update(_download_link_tags(request)) log_payload['action_meta']['bytes_downloaded'] = bytes_downloaded log_payload['action_meta']['ip'] = request.get('tech', {}).get('ip') @@ -345,6 +350,27 @@ def _scrub_headers_for_keen(payload, MAX_ITERATIONS=10): return scrubbed_payload +def _download_link_tags(request): + """Pull the ``source`` and ``tz`` tags the frontend appends to download links. + + Zips are requested straight from WB and never pass through the OSF, so the query string + is the only place the originating page and the user's timezone survive the round trip. + Both are absent for downloads that don't originate from the frontend. + """ + url = request.get('request', {}).get('url') + if not url: + return {} + + args = furl.furl(url).args + tags = {} + for tag in ('source', 'tz'): + value = args.get(tag) + if value: + tags[tag] = value[:MAX_DOWNLOAD_TAG_LENGTH] + + return tags + + def _serialize_request(request): """Serialize the original request so we can log it across celery.""" if request is None: From 8f448278221b8d08af1eb44a0e086df4db091078 Mon Sep 17 00:00:00 2001 From: Andriy Sheredko Date: Mon, 27 Jul 2026 15:49:15 +0300 Subject: [PATCH 5/5] feat(core): ENG-11826 report failed downloads to the callback --- tests/core/test_remote_logging.py | 39 +++++++++ tests/server/api/v1/test_provider.py | 87 ++++++++++++++++++- waterbutler/core/remote_logging.py | 10 ++- .../server/api/v1/provider/__init__.py | 56 +++++++++--- 4 files changed, 173 insertions(+), 19 deletions(-) diff --git a/tests/core/test_remote_logging.py b/tests/core/test_remote_logging.py index f9fde0a02b..3c9af71c87 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 e794ae7c0a..5f895f24be 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 ad73eec15a..7516a07220 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 a0defc6fee..575b28a316 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)