diff --git a/tests/core/test_remote_logging.py b/tests/core/test_remote_logging.py index 88ca8bd42..3c9af71c8 100644 --- a/tests/core/test_remote_logging.py +++ b/tests/core/test_remote_logging.py @@ -3,6 +3,213 @@ 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 + @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 = {} + + 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'] + + @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: def test_flat_dict(self): diff --git a/tests/server/api/v1/test_metadata_mixin.py b/tests/server/api/v1/test_metadata_mixin.py index 36c93e9cf..192ee11e5 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 a39eb9911..5f895f24b 100644 --- a/tests/server/api/v1/test_provider.py +++ b/tests/server/api/v1/test_provider.py @@ -165,15 +165,18 @@ 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, status_code=200) @pytest.mark.asyncio async def test_on_finish_download_zip(self, http_request): @@ -185,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') + 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): @@ -336,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') + 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 bc2d256cf..7516a0722 100644 --- a/waterbutler/core/remote_logging.py +++ b/waterbutler/core/remote_logging.py @@ -15,10 +15,14 @@ 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, - request=None): + 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 {} @@ -59,7 +63,14 @@ 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 + # 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 + 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: @@ -217,12 +228,15 @@ 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, 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,), + start_time=start_time, errors=errors, request=request, + 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, @@ -340,6 +354,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: diff --git a/waterbutler/server/api/v0/core.py b/waterbutler/server/api/v0/core.py index 543d966a2..af702e186 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 07034155f..0957d0042 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): @@ -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 = 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 2ed0695c6..34c64a744 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 = 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 3cf8ed318..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 @@ -246,6 +250,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 +259,40 @@ def on_finish(self): 'DELETE': lambda: 'delete' }[method]() + if action in {'download_file', 'download_zip'}: + completed = getattr(self, '_download_completed', status in {200, 302}) + self._send_hook(action, completed=completed, status_code=status) + return + self._send_hook(action) - def _send_hook(self, action): + 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 @@ -281,4 +317,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, status_code=status_code) diff --git a/waterbutler/server/api/v1/provider/metadata.py b/waterbutler/server/api/v1/provider/metadata.py index 2d72a7473..400e03ed2 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, **self.arguments) - 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 83d2a01a2..e9afd243e 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