diff --git a/README.md b/README.md index 949a136..c20cf64 100644 --- a/README.md +++ b/README.md @@ -183,7 +183,7 @@ FISHE_USAGE_REPORTING_ENABLED=false python3 src/fishE.py | `TRACE_USAGE_REPORTING` | unset | `off`, `false`, `0` or `no` turns reporting off, for FishE and every other trace client. | | `DO_NOT_TRACK` | unset | `1`, `true` or `yes` turns reporting off the same way. | -The test suite switches reporting off for every test (`tests/conftest.py`), and the tests that exercise it point at a loopback stub server, so running the tests never reports anything either. The client is `src/trace_client.py`, vendored as one standard-library file from [trace-client-python](https://github.com/Stephenson-Software/trace-client-python) (0.2.0); the wiring is `src/usageReporting.py`. +The test suite switches reporting off for every test (`tests/conftest.py`), and the tests that exercise it point at a loopback stub server, so running the tests never reports anything either. The client is `src/trace_client.py`, vendored as one standard-library file from [trace-client-python](https://github.com/Stephenson-Software/trace-client-python) (0.3.0); the wiring is `src/usageReporting.py`. Details: https://github.com/Stephenson-Software/trace#usage-reporting diff --git a/src/fishE.py b/src/fishE.py index 21ac6aa..0da1c9a 100644 --- a/src/fishE.py +++ b/src/fishE.py @@ -90,7 +90,7 @@ def __init__(self, interfaceType=INTERFACE_TYPE): # A slot was created or opened: the one usage event besides startup. # Nothing about the slot goes with it (see usageReporting). - self.usageReporting.report("save-loaded", tags=usageReporting.versionTags()) + self.usageReporting.report("save-loaded") # Load the chosen slot over the defaults if it has data. # diff --git a/src/trace_client.py b/src/trace_client.py index 1cca010..9997993 100644 --- a/src/trace_client.py +++ b/src/trace_client.py @@ -1,4 +1,4 @@ -"""trace-client 0.2.0 -- https://github.com/Stephenson-Software/trace-client-python +"""trace-client 0.3.0 -- https://github.com/Stephenson-Software/trace-client-python One call to report that a program was used. Copy this file into a project as is, or vendor the package; either way there is nothing else to add. Standard @@ -19,7 +19,7 @@ import urllib.request from typing import Dict, Mapping, Optional -__version__ = "0.2.0" +__version__ = "0.3.0" _LOG = logging.getLogger("trace") @@ -38,6 +38,10 @@ REASON_CONFIG = "config" REASON_NO_KEY = "no key" +#: The longest a program version may be, after trimming: the trace server's +#: limit on a tag value. +MAX_TAG_LENGTH = 255 + def environment_opts_out(environ: Optional[Mapping[str, str]] = None) -> bool: """Whether the environment asks for usage reporting to be off, via @@ -80,11 +84,16 @@ class TraceClient: so once, pointing at https://github.com/Stephenson-Software/trace#usage-reporting. + Every event carries the program's own version as the tag ``version`` -- + the third argument, required, so a ``command`` event can be tied to a + release as well as a ``startup`` one. An event's own ``version`` tag wins + over it. + :: - trace = TraceClient("https://trace.example.org", "roam", + trace = TraceClient("https://trace.example.org", "roam", __version__, key=settings.usage_key, enabled=settings.usage_reporting) - trace.report("startup", tags={"version": __version__}) + trace.report("startup") ... trace.close() # on shutdown """ @@ -92,14 +101,23 @@ class TraceClient: QUEUE_CAPACITY = 256 TIMEOUT_SECONDS = 5.0 - def __init__(self, base_url: str, application: str, *, key: Optional[str] = None, + def __init__(self, base_url: str, application: str, version: str, *, key: Optional[str] = None, enabled: bool = True) -> None: + """A client for the program named ``application``, at ``version``, + reporting to the trace server at ``base_url``. The version is sent as + the tag ``version`` on every event; a blank one, or one longer than + :data:`MAX_TAG_LENGTH` characters, is a :class:`ValueError`.""" if not base_url or not base_url.strip(): raise ValueError("base_url is required") if not application or not application.strip(): raise ValueError("application is required") + if not version or not version.strip(): + raise ValueError("version is required") + if len(version.strip()) > MAX_TAG_LENGTH: + raise ValueError("version is longer than %d characters" % MAX_TAG_LENGTH) self._endpoint = base_url.strip().rstrip("/") + "/api/metrics" self._application = application.strip() + self._version = version.strip() self._key = (key or "").strip() self._queue: Optional["queue.Queue[Optional[bytes]]"] = None self._thread: Optional[threading.Thread] = None @@ -123,7 +141,7 @@ def __init__(self, base_url: str, application: str, *, key: Optional[str] = None @classmethod def disabled(cls) -> "TraceClient": """A client that reports nothing. Useful as a default before settings are read.""" - return cls("http://disabled.invalid", "disabled", enabled=False) + return cls("http://disabled.invalid", "disabled", "disabled", enabled=False) @property def enabled(self) -> bool: @@ -136,10 +154,12 @@ def report(self, name: str, value: Optional[float] = None, tags: Optional[Mapping[str, str]] = None) -> None: """Report that ``name`` happened, with an optional numeric value and optional string tags. Returns immediately; see the class docstring.""" - if self._queue is None or not name or not name.strip(): + if self._queue is None: return try: - body = _json(self._application, name, value, tags) + if not name or not name.strip(): + return + body = _json(self._application, name, value, _with_version(tags, self._version)) self._queue.put_nowait(body) except queue.Full: _LOG.debug("[trace] queue full, dropped %s", name) @@ -183,14 +203,16 @@ def _drain(self) -> None: self._send(body) def _send(self, body: bytes) -> None: - request = urllib.request.Request( - self._endpoint, data=body, method="POST", - headers={ - "Content-Type": "application/json; charset=utf-8", - "Authorization": "Bearer " + self._key, - "User-Agent": "trace-client-python/%s (%s)" % (__version__, self._application), - }) try: + # Built inside the try: a base URL without a scheme fails here, and + # an uncaught error would kill the sender thread with a traceback. + request = urllib.request.Request( + self._endpoint, data=body, method="POST", + headers={ + "Content-Type": "application/json; charset=utf-8", + "Authorization": "Bearer " + self._key, + "User-Agent": "trace-client-python/%s (%s)" % (__version__, self._application), + }) with urllib.request.urlopen(request, timeout=self.TIMEOUT_SECONDS) as response: status = response.status response.read() @@ -207,6 +229,19 @@ def _send(self, body: bytes) -> None: _LOG.debug("[trace] trace server answered %s for %s", status, body) +def _with_version(tags: Optional[Mapping[str, str]], version: str) -> Dict[str, str]: + """The event's own tags plus ``version``, unless the event already carries + one. A copy; the caller's mapping is never modified.""" + merged: Dict[str, str] = {} + if tags: + for k, v in dict(tags).items(): + if k is not None and v is not None: + merged[str(k)] = str(v) + if "version" not in merged: + merged["version"] = version + return merged + + def _json(application: str, name: str, value: Optional[float], tags: Optional[Mapping[str, str]]) -> bytes: payload: Dict[str, object] = {"application": application, "name": name} if value is not None and value == value and value not in (float("inf"), float("-inf")): diff --git a/src/usageReporting.py b/src/usageReporting.py index 5ddef36..1ee016e 100644 --- a/src/usageReporting.py +++ b/src/usageReporting.py @@ -66,10 +66,7 @@ def isBrowserBuild(): def readVersion(path=None): - """The version from version.txt (the one run.sh prints), or None. - - None rather than a placeholder: an event without a version tag says - "unknown" more honestly than a made-up string would.""" + """The version from version.txt (the one run.sh prints), or None.""" try: with open(path or VERSION_FILE, encoding="utf-8") as versionFile: version = versionFile.read().strip() @@ -78,12 +75,11 @@ def readVersion(path=None): return version or None -def versionTags(): - """The tags every event carries: the version, when there is one.""" - version = readVersion() - if version is None: - return None - return {"version": version} +def programVersion(): + """The version the client tags every event with: version.txt's, or + "unknown" when it cannot be read, so a missing file never stops the game + from starting (the client refuses a blank version).""" + return readVersion() or "unknown" def createClient(config): @@ -99,6 +95,7 @@ def createClient(config): return TraceClient( config.usageReportingEndpoint, PROGRAM_NAME, + programVersion(), key=config.usageReportingKey, enabled=config.usageReportingEnabled, ) @@ -140,5 +137,5 @@ def start(config, output=None): client = createClient(config) if client.enabled: showNoticeOnce(config, output) - client.report("startup", tags=versionTags()) + client.report("startup") return client diff --git a/tests/test_trace_client.py b/tests/test_trace_client.py index 5025165..efe9935 100644 --- a/tests/test_trace_client.py +++ b/tests/test_trace_client.py @@ -10,7 +10,7 @@ from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer from unittest import mock -from trace_client import TraceClient, environment_opts_out +from trace_client import MAX_TAG_LENGTH, TraceClient, environment_opts_out _ENV_VARS = ("TRACE_USAGE_REPORTING", "DO_NOT_TRACK") @@ -73,28 +73,29 @@ def tearDown(self): logging.getLogger("trace").removeHandler(self.handler) def test_report_posts_the_event_to_the_metrics_endpoint_with_the_key(self): - client = TraceClient(self.base_url + "/", "MyGame", key="k-123") + client = TraceClient(self.base_url + "/", "MyGame", "1.2.3", key="k-123") client.report("startup") self.assertTrue(self.capture.arrived.wait(5), "the report should reach the server") request = self.capture.requests[0] self.assertEqual("/api/metrics", request["path"], "a trailing slash on the base URL must not double up") self.assertEqual("Bearer k-123", request["authorization"]) self.assertTrue(request["content_type"].startswith("application/json")) - self.assertEqual({"application": "MyGame", "name": "startup"}, json.loads(request["body"])) + self.assertEqual({"application": "MyGame", "name": "startup", "tags": {"version": "1.2.3"}}, + json.loads(request["body"])) client.close() def test_report_carries_value_and_tags_when_given(self): - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") client.report("world-load", 2.5, {"seed": "42", "size": 'the "big" one'}) self.assertTrue(self.capture.arrived.wait(5)) self.assertEqual({"application": "MyGame", "name": "world-load", "value": 2.5, - "tags": {"seed": "42", "size": 'the "big" one'}}, + "tags": {"seed": "42", "size": 'the "big" one', "version": "1.2.3"}}, json.loads(self.capture.requests[0]["body"])) client.close() def test_report_returns_before_the_server_answers(self): self.capture.release.clear() # a server that never replies - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") before = time.monotonic() client.report("startup") elapsed = time.monotonic() - before @@ -107,7 +108,7 @@ def test_report_does_not_raise_when_nothing_is_listening(self): dead_port = probe.server_address[1] probe.shutdown() probe.server_close() - client = TraceClient("http://127.0.0.1:%d" % dead_port, "MyGame", key="k") + client = TraceClient("http://127.0.0.1:%d" % dead_port, "MyGame", "1.2.3", key="k") client.report("startup") # must not raise deadline = time.monotonic() + 5 while time.monotonic() < deadline and not any("could not deliver" in r.getMessage() for r in self.log): @@ -118,16 +119,16 @@ def test_report_does_not_raise_when_nothing_is_listening(self): def test_report_does_not_raise_when_the_server_rejects_the_key(self): self.capture.reply_status = 401 - client = TraceClient(self.base_url, "MyGame", key="revoked") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="revoked") client.report("startup") self.assertTrue(self.capture.arrived.wait(5)) client.close() self.assertTrue(any("answered 401" in r.getMessage() for r in self.log), [r.getMessage() for r in self.log]) def test_disabled_client_sends_nothing(self): - for client in (TraceClient(self.base_url, "MyGame", key="k", enabled=False), - TraceClient(self.base_url, "MyGame"), - TraceClient(self.base_url, "MyGame", key=" "), + for client in (TraceClient(self.base_url, "MyGame", "1.2.3", key="k", enabled=False), + TraceClient(self.base_url, "MyGame", "1.2.3"), + TraceClient(self.base_url, "MyGame", "1.2.3", key=" "), TraceClient.disabled()): self.assertFalse(client.enabled) client.report("startup") @@ -136,7 +137,7 @@ def test_disabled_client_sends_nothing(self): self.assertEqual([], self.capture.requests) def test_disabled_reason_is_none_when_the_client_reports(self): - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") self.assertTrue(client.enabled) self.assertIsNone(client.disabled_reason) client.close() @@ -144,17 +145,17 @@ def test_disabled_reason_is_none_when_the_client_reports(self): self.assertIsNone(client.disabled_reason, "but the reason describes how it was built") def test_disabled_reason_names_the_config_flag_or_the_missing_key(self): - self.assertEqual("config", TraceClient(self.base_url, "MyGame", key="k", enabled=False).disabled_reason) + self.assertEqual("config", TraceClient(self.base_url, "MyGame", "1.2.3", key="k", enabled=False).disabled_reason) self.assertEqual("config", TraceClient.disabled().disabled_reason) - self.assertEqual("no key", TraceClient(self.base_url, "MyGame").disabled_reason) - self.assertEqual("no key", TraceClient(self.base_url, "MyGame", key=" ").disabled_reason) - self.assertEqual("config", TraceClient(self.base_url, "MyGame", enabled=False).disabled_reason, + self.assertEqual("no key", TraceClient(self.base_url, "MyGame", "1.2.3").disabled_reason) + self.assertEqual("no key", TraceClient(self.base_url, "MyGame", "1.2.3", key=" ").disabled_reason) + self.assertEqual("config", TraceClient(self.base_url, "MyGame", "1.2.3", enabled=False).disabled_reason, "the config flag is checked before the key") def _assert_environment_disables(self, variable, value): with mock.patch.dict(os.environ, {variable: value}): self.assertTrue(environment_opts_out(), "%s=%r should opt out" % (variable, value)) - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") self.assertFalse(client.enabled, "%s=%r should disable the client" % (variable, value)) self.assertEqual("environment", client.disabled_reason) client.report("startup") @@ -177,7 +178,7 @@ def test_other_environment_values_leave_the_program_setting_in_charge(self): ("DO_NOT_TRACK", "off")): with mock.patch.dict(os.environ, {variable: value}): self.assertFalse(environment_opts_out(), "%s=%r is not an opt-out" % (variable, value)) - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") self.assertTrue(client.enabled, "%s=%r must not disable the client" % (variable, value)) self.assertIsNone(client.disabled_reason) client.close() @@ -186,17 +187,17 @@ def test_other_environment_values_leave_the_program_setting_in_charge(self): def test_environment_wins_over_the_config_flag_and_over_the_key(self): # enabled=True with a key, and the environment still says no. with mock.patch.dict(os.environ, {"TRACE_USAGE_REPORTING": "off"}): - client = TraceClient(self.base_url, "MyGame", key="k", enabled=True) + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k", enabled=True) self.assertEqual("environment", client.disabled_reason) client.close() # enabled=False AND the environment: the environment is the reason. with mock.patch.dict(os.environ, {"DO_NOT_TRACK": "1"}): self.assertEqual("environment", - TraceClient(self.base_url, "MyGame", key="k", enabled=False).disabled_reason) - self.assertEqual("environment", TraceClient(self.base_url, "MyGame").disabled_reason, + TraceClient(self.base_url, "MyGame", "1.2.3", key="k", enabled=False).disabled_reason) + self.assertEqual("environment", TraceClient(self.base_url, "MyGame", "1.2.3").disabled_reason, "the environment is checked before the key too") # Once the variable is gone, the program's own setting is back in charge. - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") self.assertTrue(client.enabled) client.report("startup") self.assertTrue(self.capture.arrived.wait(5)) @@ -210,24 +211,93 @@ def test_environment_opts_out_accepts_an_explicit_mapping(self): def test_user_agent_names_the_client_version(self): from trace_client import __version__ - self.assertEqual("0.2.0", __version__) - client = TraceClient(self.base_url, "MyGame", key="k") + self.assertEqual("0.3.0", __version__) + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") client.report("startup") self.assertTrue(self.capture.arrived.wait(5)) client.close() - self.assertEqual("trace-client-python/0.2.0 (MyGame)", self.capture.requests[0]["user_agent"]) + self.assertEqual("trace-client-python/0.3.0 (MyGame)", self.capture.requests[0]["user_agent"]) def test_report_ignores_a_blank_name(self): - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") client.report("") client.report(" ") client.close() self.assertFalse(self.capture.arrived.wait(0.3)) + def test_report_does_not_raise_for_a_name_that_is_not_a_string(self): + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") + client.report(123) # must not raise + client.close() + self.assertFalse(self.capture.arrived.wait(0.3), "a report that could not be built is dropped") + self.assertTrue(any("could not queue 123" in r.getMessage() for r in self.log), + [r.getMessage() for r in self.log]) + self.assertTrue(all(r.levelno == logging.DEBUG for r in self.log)) + + def test_a_base_url_without_a_scheme_is_logged_not_a_dead_thread(self): + crashes = [] + with mock.patch.object(threading, "excepthook", crashes.append): + client = TraceClient("trace.example.org", "MyGame", "1.2.3", key="k") + client.report("startup") + client.report("shutdown") + client.close() + self.assertEqual([], crashes, "the sender thread must not die with a traceback on stderr") + failures = [r for r in self.log if "could not deliver" in r.getMessage()] + self.assertEqual(2, len(failures), "each report is logged and the thread keeps going: %s" + % [r.getMessage() for r in self.log]) + self.assertTrue(all(r.levelno == logging.DEBUG for r in self.log)) + def test_constructor_rejects_a_missing_base_url_or_application(self): for base_url, application in ((None, "MyGame"), (" ", "MyGame"), ("http://x", None), ("http://x", "")): with self.assertRaises(ValueError): - TraceClient(base_url, application) + TraceClient(base_url, application, "1.2.3") + + def test_constructor_rejects_a_missing_blank_or_overlong_version(self): + for version in (None, "", " ", "9" * (MAX_TAG_LENGTH + 1)): + with self.assertRaises(ValueError, msg=repr(version)): + TraceClient(self.base_url, "MyGame", version, key="k") + with self.assertRaises(TypeError, msg="the version is required, not optional"): + TraceClient(self.base_url, "MyGame", key="k") + # Exactly the limit is fine, and so is an overlong-looking one that trims to it. + TraceClient(self.base_url, "MyGame", "9" * MAX_TAG_LENGTH, enabled=False) + TraceClient(self.base_url, "MyGame", " " + "9" * MAX_TAG_LENGTH + " ", enabled=False) + + def test_report_tags_a_command_with_the_program_version_trimmed(self): + client = TraceClient(self.base_url, "MyGame", " 2.0.0-SNAPSHOT ", key="k") + client.report("command", tags={"name": "home"}) + self.assertTrue(self.capture.arrived.wait(5)) + client.close() + self.assertEqual('{"application":"MyGame","name":"command",' + '"tags":{"name":"home","version":"2.0.0-SNAPSHOT"}}', + self.capture.requests[0]["body"]) + + def test_report_an_events_own_version_tag_wins_over_the_program_version(self): + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") + tags = {"version": "9.9.9"} + client.report("startup", tags=tags) + self.assertTrue(self.capture.arrived.wait(5)) + client.close() + self.assertEqual('{"application":"MyGame","name":"startup","tags":{"version":"9.9.9"}}', + self.capture.requests[0]["body"]) + self.assertEqual({"version": "9.9.9"}, tags, "the caller's dict is not modified") + + def test_report_never_modifies_the_callers_tags(self): + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") + tags = {"name": "home"} + client.report("command", tags=tags) + self.assertTrue(self.capture.arrived.wait(5)) + client.close() + self.assertEqual({"name": "home"}, tags) + self.assertEqual({"name": "home", "version": "1.2.3"}, + json.loads(self.capture.requests[0]["body"])["tags"]) + + def test_with_version_never_modifies_the_callers_mapping(self): + from trace_client import _with_version + tags = {"name": "home"} + merged = _with_version(tags, "1.2.3") + self.assertEqual({"name": "home"}, tags) + self.assertEqual({"name": "home", "version": "1.2.3"}, merged) + self.assertEqual({"version": "1.2.3"}, _with_version(None, "1.2.3")) def test_json_drops_nan_and_none_tags(self): from trace_client import _json @@ -236,7 +306,7 @@ def test_json_drops_nan_and_none_tags(self): def test_queue_is_bounded_and_drops_rather_than_grows(self): self.capture.release.clear() # hold the sender on the first report - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") flood = TraceClient.QUEUE_CAPACITY * 3 for _ in range(flood): client.report("flood") @@ -251,14 +321,14 @@ def test_close_sends_what_was_just_queued_before_stopping(self): # races the sender thread and is lost a good fraction of the time; # 30 back-to-back report()+close() pairs make that fraction visible. for i in range(30): - client = TraceClient(self.base_url, "MyCli", key="k") + client = TraceClient(self.base_url, "MyCli", "1.2.3", key="k") client.report("startup", tags={"run": str(i)}) client.close() self.assertEqual(30, len(self.capture.requests), "every report()+close() pair must deliver") def test_close_still_returns_within_the_timeout_when_the_server_hangs(self): self.capture.release.clear() # never answers - client = TraceClient(self.base_url, "MyCli", key="k") + client = TraceClient(self.base_url, "MyCli", "1.2.3", key="k") client.report("startup") before = time.monotonic() client.close(timeout=1.0) @@ -266,7 +336,7 @@ def test_close_still_returns_within_the_timeout_when_the_server_hangs(self): self.capture.release.set() def test_close_is_prompt_and_idempotent(self): - client = TraceClient(self.base_url, "MyGame", key="k") + client = TraceClient(self.base_url, "MyGame", "1.2.3", key="k") client.report("startup") before = time.monotonic() client.close() diff --git a/tests/test_usageReporting.py b/tests/test_usageReporting.py index d9a6d7c..bc843b3 100644 --- a/tests/test_usageReporting.py +++ b/tests/test_usageReporting.py @@ -98,7 +98,7 @@ def test_the_version_tag_is_what_version_txt_says(monkeypatch, tmp_path): versionFile.write_text("9.9.9-TEST\n") monkeypatch.setattr(usageReporting, "VERSION_FILE", str(versionFile)) - assert usageReporting.versionTags() == {"version": "9.9.9-TEST"} + assert usageReporting.programVersion() == "9.9.9-TEST" def test_the_repository_version_file_is_the_one_run_sh_prints(): @@ -111,7 +111,9 @@ def test_the_repository_version_file_is_the_one_run_sh_prints(): assert usageReporting.readVersion() == repositoryVersion.strip() -def test_a_missing_or_empty_version_file_means_no_version_tag(monkeypatch, tmp_path): +def test_a_missing_or_empty_version_file_means_an_unknown_version( + monkeypatch, tmp_path +): empty = tmp_path / "version.txt" empty.write_text(" \n") assert usageReporting.readVersion(str(tmp_path / "absent.txt")) is None @@ -119,7 +121,7 @@ def test_a_missing_or_empty_version_file_means_no_version_tag(monkeypatch, tmp_p monkeypatch.setattr(usageReporting, "VERSION_FILE", str(tmp_path / "absent.txt")) - assert usageReporting.versionTags() is None + assert usageReporting.programVersion() == "unknown" # -- building the client ------------------------------------------------------