diff --git a/docs/launcher.md b/docs/launcher.md index 7b162853..c55b1de2 100644 --- a/docs/launcher.md +++ b/docs/launcher.md @@ -174,6 +174,10 @@ directly. Every address is https (plain http only to this PC), a redirect to htt sent on when a redirect leaves the host it was meant for (`launcher/net.py`). A manifest that does not give a file's size and sha256 is refused. +GitHub allows an address 60 such requests an hour. The Updates row and F5 therefore start no check within a minute +of the last one (`FORCED_CHECK_PAUSE`), and a check GitHub refuses says when the allowance is whole again, from the +answer's `X-RateLimit-Reset` (`feed.retry_text`). A failed check is one line in `launcher.log`. + ### In the background The player never waits for a download and play is never interrupted. A check that finds a newer release (the check diff --git a/launcher/feed.py b/launcher/feed.py index 368dc579..acb8236d 100644 --- a/launcher/feed.py +++ b/launcher/feed.py @@ -14,6 +14,7 @@ The feed (app//feed.json, or the player's override in settings) is eith """ import json import re +import time import urllib.parse from pathlib import Path @@ -78,6 +79,30 @@ def _check_manifest(m, where): return m +def retry_text(headers, now=None): + """When GitHub takes requests again, for the message of a refused one: "after 14:32 (in 25 minutes)". From + X-RateLimit-Reset, the time the hourly allowance is whole again, when the response says the allowance is used + up (X-RateLimit-Remaining: 0), else from Retry-After, the seconds to wait. '' when the response says neither + or says something that cannot be right (more than a day).""" + now = time.time() if now is None else now + try: + if headers.get('X-RateLimit-Remaining') == '0' and headers.get('X-RateLimit-Reset'): + wait = int(headers.get('X-RateLimit-Reset')) - now + elif headers.get('Retry-After'): + wait = int(headers.get('Retry-After')) + else: + return '' + except (AttributeError, TypeError, ValueError): + return '' + if wait > 86400: + return '' + if wait <= 0: # the allowance is whole again by this PC's clock + return 'in a minute' + minutes = int(-(-wait // 60)) + return (f'after {time.strftime("%H:%M", time.localtime(now + wait))} ' + f'(in {minutes} minute{"" if minutes == 1 else "s"})') + + def _github(feed, channel, token, version): api = feed.get('api', GITHUB_API).rstrip('/') headers = {'Accept': 'application/vnd.github+json', 'X-GitHub-Api-Version': '2022-11-28'} @@ -89,8 +114,9 @@ def _github(feed, channel, token, version): code = getattr(e, 'code', None) if code == 404: raise FeedError(f'no releases found for {feed["repo"]} (a private repository needs a token)') from e - if code == 403: - raise FeedError('GitHub refused the request (rate limit); try again in an hour') from e + if code in (403, 429): # GitHub answers either when the allowance of requests is used up + when = retry_text(getattr(e, 'headers', None)) + raise FeedError(f'GitHub refused the request (rate limit); try again {when or "in an hour"}') from e raise FeedError(f'GitHub could not be reached: {e}') from e # The API lists the newest release first: the first one the channel takes that has a manifest is the answer. for r in releases: diff --git a/launcher/jobs.py b/launcher/jobs.py index e6bfc9e6..f90206f9 100644 --- a/launcher/jobs.py +++ b/launcher/jobs.py @@ -13,6 +13,16 @@ RECHECK = 3600 # seconds between update checks while the launcher stays open, PENDING, RUNNING, DONE, SKIPPED, FAILED = 'pending', 'running', 'done', 'skipped', 'failed' +# Failures whose message says all there is to say: the log gets one line for them (failure_line), not a traceback. +# A refused update check wrote 22 lines of two tracebacks into launcher.log each time. +PLAIN_FAILURES = (feed.FeedError,) + + +def failure_line(e): + """A failure in one line for the log: its kind, its message and what it came from.""" + cause = e.__cause__ + return f'{type(e).__name__}: {e}' + (f' ({type(cause).__name__}: {cause})' if cause else '') + STEPS = { 'tools': ('Gather Build Tools', 'Downloading the compiler and libraries the build uses. This happens once and ' 'takes about 170 MB.'), @@ -230,7 +240,7 @@ class Job: self.result = 'cancelled' else: self.result, self.error = 'failed', str(e) or type(e).__name__ - self.ctx.log(traceback.format_exc()) + self.ctx.log(failure_line(e) if isinstance(e, PLAIN_FAILURES) else traceback.format_exc()) finally: for s in self.steps: if s.state == RUNNING: diff --git a/launcher/ui/app.py b/launcher/ui/app.py index 8a6bf5b9..16bb29a7 100644 --- a/launcher/ui/app.py +++ b/launcher/ui/app.py @@ -184,6 +184,11 @@ def drop_partial_image(game_dir): pass +# Seconds after an update check before the Updates row or F5 starts another. Each check is a request to GitHub, +# which allows 60 an hour for an address: a player who selected the row 25 times in 90 seconds used the allowance +# up, and every check of the next hour was refused. +FORCED_CHECK_PAUSE = 60 + # How long an update's rebuild takes, for the Updates row. No single figure holds: a version that changed little # compiles a few files and links, minutes; one that changed the lifter translates and compiles the game's code again, # and one that changed what the shaders are built with builds all of them into the graphics driver's cache again @@ -1312,6 +1317,11 @@ class App: return if not force and time.time() - self.settings.get('last_check', 0) < 600 and self.release: return + if force and time.time() - self.check_started < FORCED_CHECK_PAUSE: + self.message = 'NX2navi looked for updates less than a minute ago.' + if self.screen == 'home': + self.show('home', self.focus) + return self.check_error = '' self.check_started = time.time() self.check = jobs.CheckJob(self.ctx).start() diff --git a/tests/launcher_test.py b/tests/launcher_test.py index 1660b9c7..98f4df8a 100644 --- a/tests/launcher_test.py +++ b/tests/launcher_test.py @@ -719,6 +719,63 @@ class FeedTest(Tmp): self.assertTrue(any(h.get('Authorization') == 'Bearer secret' for _, h in srv.hits)) self.assertEqual(feed.plain_notes('## Head\n- **One**\n* `Two`\n'), ['Head', 'One', 'Two']) + def test_a_refused_check_says_when_to_try_again(self): + """GitHub's answer to a request over the hourly allowance carries the time the allowance is whole again: + the message names it, and the log gets one line for the failed check, not two tracebacks.""" + srv = self.serve_github() + reset = int(time.time()) + 1500 + self.routes['/repos/o/r/releases?per_page=20'] = ( + 403, {'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': str(reset)}, b'{"message": "rate limit"}') + f = {'type': 'github', 'repo': 'o/r', 'api': srv.url.rstrip('/')} + with self.assertRaises(feed.FeedError) as c: + feed.latest(f, 'stable') + at = time.strftime('%H:%M', time.localtime(reset)) + self.assertRegex(str(c.exception), rf'^GitHub refused the request \(rate limit\); try again after {at} ' + r'\(in 2[45] minutes\)$') + # the header's forms + now = 1700000000 + text = feed.retry_text + self.assertTrue(text({'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': str(now + 61)}, now) + .endswith(' (in 2 minutes)')) + self.assertTrue(text({'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': str(now + 60)}, now) + .endswith(' (in 1 minute)')) + self.assertEqual(text({'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': str(now - 5)}, now), 'in a minute') + self.assertTrue(text({'Retry-After': '120'}, now).endswith(' (in 2 minutes)')) + self.assertTrue(text({'Retry-After': '120'}, now).startswith('after ')) + self.assertEqual(text({'X-RateLimit-Remaining': '12', 'X-RateLimit-Reset': str(now + 600)}, now), '') + for nothing in ({}, None, {'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': 'soon'}, + {'X-RateLimit-Remaining': '0', 'X-RateLimit-Reset': str(now + 10 ** 6)}): + self.assertEqual(text(nothing, now), '') + # a refusal without the headers keeps the old advice + self.routes['/repos/o/r/releases?per_page=20'] = (403, {}, b'{}') + with self.assertRaises(feed.FeedError) as c: + feed.latest(f, 'stable') + self.assertEqual(str(c.exception), 'GitHub refused the request (rate limit); try again in an hour') + # the job: one line in the log + ctx = Context(self.layout) + self.addCleanup(ctx._file.close) + ctx.settings['feed_repo'] = 'o/r' + with mock.patch.object(feed, 'GITHUB_API', srv.url.rstrip('/')): + j = jobs.CheckJob(ctx).run_inline() + self.assertEqual((j.result, j.error), ('failed', 'GitHub refused the request (rate limit); try again in an hour')) + ctx._file.flush() + log = (self.layout.logs / 'launcher.log').read_text(encoding='utf-8').splitlines()[1:] + self.assertEqual(len(log), 1, log) + self.assertIn('FeedError: GitHub refused the request (rate limit); try again in an hour (HTTPError: HTTP Error ' + '403', log[0]) + self.assertNotIn('Traceback', log[0]) + + def test_other_failures_keep_their_traceback(self): + ctx = Context(self.layout) + self.addCleanup(ctx._file.close) + j = jobs.Job(ctx, []) + j.run = lambda: [][1] + j.run_inline() + ctx._file.flush() + log = (self.layout.logs / 'launcher.log').read_text(encoding='utf-8') + self.assertIn('Traceback (most recent call last)', log) + self.assertIn('IndexError', log) + def test_url_feed_and_update(self): z = make_app_zip(self.tmp, '0.9.0') (self.tmp / feed.MANIFEST).write_text(json.dumps(manifest_for(z, '0.9.0'))) @@ -3732,6 +3789,29 @@ class UpdateTextTest(Tmp): self.assertIn('half an hour or more', app.UPDATE_TAKES) +class ForcedCheckTest(Tmp): + def test_one_forced_update_check_a_minute(self): + """Selecting the Updates row (or F5) again within a minute of the last check starts no request: 25 of them + in 90 seconds used up GitHub's hourly allowance for a player.""" + from launcher.ui import app + App, a = mock_app(self, self.tmp / 'game') + a.screen = 'home' + with mock.patch('launcher.ui.app.jobs.CheckJob') as check: + a.check_started = time.time() - 10 + App.check_now(a, force=True) + check.assert_not_called() + self.assertEqual(a.message, 'NX2navi looked for updates less than a minute ago.') + a.show.assert_called_once_with('home', a.focus) + a.check_started = time.time() - app.FORCED_CHECK_PAUSE - 1 + App.check_now(a, force=True) + check.assert_called_once() + self.assertGreater(a.check_started, time.time() - 5) + # the launcher's own checks (at start, every hour) are not held back by it + a.check, a.check_started = None, time.time() - 10 + App.check_now(a) + self.assertEqual(check.call_count, 2) + + class StartScriptTest(Tmp): """launcher/start.pyw when the version cannot be imported: with a version to go back to it ends with code 86 at once and shows no message box, so the stub's six-second wait sees the code and rolls back."""