"""Errors go to the log chat as a `python` code block: full tracebacks, split not shortened, secrets removed, no floods.""" import asyncio import gc import logging import threading from types import SimpleNamespace import pytest from telethon import errors, types from app import errorlog from app.errorlog import ErrorReporter, TelegramLogHandler, format_exception, redact, split_report from app.tgutil import utf16_len from .harness import App, norm CHAT = -1002525172451 TOKEN = "123456:ABCdefGHIjklMNOpqrSTUvwxYZ" class FakeSender: """The bot's Telegram connection, as far as the reporter uses it.""" def __init__(self, *, member=True, connected=True, authorized=True): self.member, self.connected, self.authorized = member, connected, authorized self.sent = [] # (peer, text, entities, link_preview) self.lookups = [] self.signed_in = [] self.fail_send = None async def get_input_entity(self, chat_id): self.lookups.append(chat_id) if not self.member: raise ValueError(f"Could not find the input entity for {chat_id}") return types.InputPeerChannel(2525172451, 1) async def send_message(self, peer, text, *, formatting_entities=None, link_preview=None): if self.fail_send is not None: raise self.fail_send self.sent.append((peer, text, formatting_entities, link_preview)) def is_connected(self): return self.connected async def connect(self): self.connected = True async def is_user_authorized(self): return self.authorized async def sign_in(self, bot_token=None): self.signed_in.append(bot_token) self.authorized = True @property def texts(self): return [s[1] for s in self.sent] def reporter(client, **kw): kw.setdefault("gap", 0) kw.setdefault("part_gap", 0) kw.setdefault("bot_token", TOKEN) return ErrorReporter(client, kw.pop("chat_id", CHAT), **kw) async def drain(rep, timeout=5): await asyncio.wait_for(rep._queue.join(), timeout) def boom(depth=0): """An exception chain like the one in the screenshot: a cause, then the error it led to.""" try: try: raise KeyError("inner") except KeyError as e: raise RuntimeError("outer") from e except RuntimeError as e: return e # ------------------------------------------------------------------------------------ text helpers def test_short_reports_stay_in_one_piece(): assert split_report("hello") == ["hello"] text = "x" * 3800 assert split_report(text) == [text] def test_long_reports_are_split_at_line_breaks_and_nothing_is_lost(): lines = [f" File \"/app/module_{i}.py\", line {i}, in function_{i}" for i in range(300)] text = "Unhandled exception:\n" + "\n".join(lines) parts = split_report(text) assert len(parts) > 1 assert all(len(p) <= 4096 for p in parts) n = len(parts) assert [p.split("\n", 1)[0] for p in parts] == [f"(part {i}/{n})" for i in range(1, n + 1)] body = "\n".join(p.split("\n", 1)[1] for p in parts) assert body == text # the same lines in the same order, none dropped, none cut in half def test_one_enormous_line_is_cut_into_pieces_not_dropped(): text = "Error: " + "y" * 10000 parts = split_report(text) assert len(parts) > 1 and all(len(p) <= 4096 for p in parts) body = "".join(p.split("\n", 1)[1] for p in parts) assert body.replace("\n", "") == text # every character is there; the only addition is a line break at each cut def test_redact_removes_secrets_longest_first(): out = redact(f"token {TOKEN} and hunter2hunter2 and ab", [TOKEN, "hunter2hunter2", "ab", "", None]) assert out == "token *** and *** and ab" # a 2-letter "secret" would mangle ordinary words, so it is left alone assert redact("keep me", [TOKEN]) == "keep me" assert redact("p@ssw0rd-long p@ssw0rd", ["p@ssw0rd", "p@ssw0rd-long"]) == "*** ***" def test_traceback_text_contains_the_whole_chain(): text = format_exception(boom()) assert text.startswith("Traceback (most recent call last):") assert "KeyError: 'inner'" in text and "RuntimeError: outer" in text assert "The above exception was the direct cause of the following exception:" in text # ---------------------------------------------------------------------------------------- delivery def test_a_report_is_sent_as_a_python_code_block(): async def go(): client = FakeSender() rep = reporter(client) rep.start() rep.submit("Unhandled exception in background task :", format_exception(boom())) await drain(rep) (peer, text, ents, preview), = client.sent assert text.startswith("Unhandled exception in background task :\n\nTraceback (most recent call last):") assert "The above exception was the direct cause of the following exception:" in text assert text.rstrip().endswith("RuntimeError: outer") # one code block over the whole message, language "python" (ent,) = ents assert isinstance(ent, types.MessageEntityPre) and ent.language == "python" assert (ent.offset, ent.length) == (0, utf16_len(text)) and preview is False assert client.lookups == [CHAT] await rep.stop() asyncio.run(go()) def test_the_code_block_length_counts_utf16_units(): async def go(): client = FakeSender() rep = reporter(client) rep.start() rep.submit("Fehler πŸ˜€ in Aufgabe:", "Traceback:\n ValueError: Grâße β‰  πŸ˜€πŸ˜€") await drain(rep) _, text, ents, _ = client.sent[0] assert ents[0].length == utf16_len(text) and utf16_len(text) > len(text) # emoji take two units await rep.stop() asyncio.run(go()) def test_a_long_traceback_is_sent_in_several_messages_and_every_line_arrives(): async def go(): client = FakeSender() rep = reporter(client) rep.start() tb = "Traceback (most recent call last):\n" + "\n".join(f' File "/app/m{i}.py", line {i}, in f{i}' for i in range(400)) + "\nValueError: deep" rep.submit("Unhandled exception in handler h_x (user 1):", tb) await drain(rep) assert len(client.sent) > 1 for _, text, ents, _ in client.sent: assert len(text) <= 4096 and ents[0].length == utf16_len(text) and ents[0].language == "python" joined = "\n".join(t.split("\n", 1)[1] for t in client.texts) assert "ValueError: deep" in joined and joined.count("File \"/app/m") == 400 assert client.texts[0].startswith(f"(part 1/{len(client.sent)})") await rep.stop() asyncio.run(go()) def test_secrets_never_leave_the_bot(): async def go(): client = FakeSender() # the bot token is hidden even though it is only given as the login token, not in the list of secrets rep = reporter(client, secrets=["hunter2hunter2", "SESSIONTEXT123456"]) rep.start() rep.submit(f"login with {TOKEN} failed:", "OperationalError: password hunter2hunter2 wrong, session SESSIONTEXT123456") await drain(rep) text = client.texts[0] assert TOKEN not in text and "hunter2hunter2" not in text and "SESSIONTEXT123456" not in text assert text.count("***") == 3 await rep.stop() asyncio.run(go()) def test_secrets_are_removed_even_when_a_text_is_split_across_parts(): async def go(): client = FakeSender() rep = reporter(client, secrets=["hunter2hunter2"]) rep.start() lines = ["line %d hunter2hunter2" % i for i in range(500)] rep.submit("Many lines:", "\n".join(lines)) await drain(rep) assert len(client.sent) > 1 and not any("hunter2" in t for t in client.texts) await rep.stop() asyncio.run(go()) # --------------------------------------------------------------------------------------- the sources def test_a_forgotten_background_task_is_reported_like_in_the_screenshot(): async def go(): client = FakeSender() rep = reporter(client) rep.start() loop = asyncio.get_running_loop() loop.set_exception_handler(rep.loop_exception_handler) async def boom_task(): raise boom() t = loop.create_task(boom_task()) await asyncio.sleep(0.05) # it ran and failed; nobody looked at the result del t gc.collect() await asyncio.sleep(0.05) await drain(rep) text = client.texts[0] assert text.startswith("Unhandled exception in background task :\n\nTraceback") assert "RuntimeError: outer" in text and "The above exception was the direct cause" in text await rep.stop() asyncio.run(go()) def test_named_tasks_keep_their_name_and_other_loop_errors_their_message(): async def go(): client = FakeSender() rep = reporter(client) rep.start() loop = asyncio.get_running_loop() async def noop(): raise ValueError("x") task = loop.create_task(noop(), name="cleanup-job") await asyncio.sleep(0) await asyncio.sleep(0) calls = [] loop.default_exception_handler = lambda ctx: calls.append(ctx) # the normal log line still happens rep.loop_exception_handler(loop, {"message": "Task exception was never retrieved", "exception": task.exception(), "future": task}) rep.loop_exception_handler(loop, {"message": "Fatal error on transport", "exception": OSError("pipe closed")}) rep.loop_exception_handler(loop, {"message": "Something odd without an exception"}) await drain(rep) assert client.texts[0].startswith("Unhandled exception in background task cleanup-job:") assert client.texts[1] == "Fatal error on transport:\n\nOSError: pipe closed" assert client.texts[2].startswith("Something odd without an exception:") assert len(calls) == 3 await rep.stop() asyncio.run(go()) def test_the_logging_handler_forwards_errors_with_their_traceback(): async def go(): client = FakeSender() rep = reporter(client) rep.start() handler = TelegramLogHandler(rep) root = logging.getLogger() root.addHandler(handler) try: try: raise boom() except RuntimeError: logging.getLogger("app.common").exception("Unhandled exception in handler h_posts (user 1)") logging.getLogger("app.common").error("Telegram refused a request") # no traceback logging.getLogger("app.common").warning("only a warning") # below ERROR: not sent logging.getLogger("telethon.network").error("Connection lost") # other libraries get a tag logging.getLogger("app.errorlog").error("our own message must not loop") logging.getLogger("asyncio").error("asyncio has its own path") await asyncio.sleep(0.05) await drain(rep) finally: root.removeHandler(handler) assert len(client.sent) == 3, client.texts assert client.texts[0].startswith("Unhandled exception in handler h_posts (user 1):\n\nTraceback") assert "The above exception was the direct cause of the following exception:" in client.texts[0] assert client.texts[1] == "Telegram refused a request" assert client.texts[2] == "[telethon.network] Connection lost" await rep.stop() asyncio.run(go()) def test_a_failing_handler_in_the_bot_reaches_the_log_chat_end_to_end(tmp_path): """A real handler fails; guard() logs it; the log handler sends it as a code block with the whole chain.""" async def go(): client = FakeSender() rep = reporter(client) rep.start() handler = TelegramLogHandler(rep) logging.getLogger().addHandler(handler) app = App(tmp_path) await app.start() app.ctx.reporter = rep async def broken(): raise boom() app.db.list_channels = broken # /channels now fails the way a database outage would try: await app.text("/channels") await asyncio.sleep(0.05) await drain(rep) finally: logging.getLogger().removeHandler(handler) assert "Something went wrong: RuntimeError" in norm(app.out.last_text) # the user is told too text = client.texts[0] assert text.startswith("Unhandled exception in handler h_channels (user 1):\n\nTraceback") assert "KeyError: 'inner'" in text and "RuntimeError: outer" in text assert "The above exception was the direct cause of the following exception:" in text await app.db.close() await rep.stop() asyncio.run(go()) def test_a_forgotten_background_task_that_fails_reaches_the_log_chat(tmp_path): async def go(): client = FakeSender() rep = reporter(client) rep.start() asyncio.get_running_loop().set_exception_handler(rep.loop_exception_handler) async def fails(): raise RuntimeError("background failure") asyncio.get_running_loop().create_task(fails()) # nobody awaits it await asyncio.sleep(0.1) gc.collect() await asyncio.sleep(0.05) await drain(rep) assert client.texts[0].startswith("Unhandled exception in background task :") assert "RuntimeError: background failure" in client.texts[0] await rep.stop() asyncio.run(go()) def test_a_crash_of_the_whole_bot_is_sent_directly_even_when_disconnected(): async def go(): client = FakeSender(connected=False, authorized=False) rep = reporter(client) # never started: the crash path does not depend on the worker await rep.report_fatal("The bot stopped because of an unhandled exception", boom()) assert client.connected and client.signed_in == [TOKEN] (peer, text, ents, _), = client.sent assert text.startswith("The bot stopped because of an unhandled exception:\n\nTraceback") assert "RuntimeError: outer" in text and ents[0].language == "python" asyncio.run(go()) def test_a_failing_crash_report_never_raises(): async def go(): client = FakeSender() client.fail_send = errors.ChatWriteForbiddenError(request=None) rep = reporter(client) await rep.report_fatal("The bot stopped", boom()) # must not raise (the bot is going down anyway) await reporter(FakeSender(), chat_id=None).report_fatal("x", boom()) asyncio.run(go()) # ------------------------------------------------------------------------------- flood protection def test_identical_errors_are_merged_and_counted(monkeypatch): async def go(): now = [1000.0] monkeypatch.setattr(errorlog, "time", SimpleNamespace(monotonic=lambda: now[0])) client = FakeSender() rep = reporter(client, dedupe_seconds=60) rep.start() for _ in range(5): rep.submit("Unhandled exception in handler h:", "Traceback:\nValueError: same") now[0] += 1 rep.submit("Unhandled exception in handler h:", "Traceback:\nValueError: different") # another error: not merged await drain(rep) assert len(client.sent) == 2 now[0] += 100 # a minute and a half later the same error is news again, and says how often it came meanwhile rep.submit("Unhandled exception in handler h:", "Traceback:\nValueError: same") await drain(rep) assert len(client.sent) == 3 and "(+4 identical report(s) suppressed)" in client.texts[2] assert "suppressed" not in client.texts[0] await rep.stop() asyncio.run(go()) def test_a_storm_of_different_errors_is_limited_per_minute(monkeypatch): async def go(): now = [5000.0] monkeypatch.setattr(errorlog, "time", SimpleNamespace(monotonic=lambda: now[0])) client = FakeSender() rep = reporter(client, per_minute=3) rep.start() for i in range(10): rep.submit(f"error number {i}:", f"ValueError: {i}") await drain(rep) assert len(client.sent) == 3 # the first three, the other seven are counted now[0] += 61 rep.submit("error after the storm:", "ValueError: later") await drain(rep) assert len(client.sent) == 4 and "(7 report(s) were skipped because too many errors came in)" in client.texts[3] await rep.stop() asyncio.run(go()) def test_not_being_allowed_to_write_to_the_chat_silences_the_reporter(monkeypatch): async def go(): now = [10.0] monkeypatch.setattr(errorlog, "time", SimpleNamespace(monotonic=lambda: now[0])) client = FakeSender() client.fail_send = errors.ChatWriteForbiddenError(request=None) rep = reporter(client) rep.start() rep.submit("first:", "ValueError: 1") await drain(rep) assert client.sent == [] and client.lookups == [CHAT] rep.submit("second:", "ValueError: 2") # muted: not even tried await asyncio.sleep(0.05) assert client.lookups == [CHAT] and rep._queue.qsize() == 0 now[0] += errorlog.MUTE_SECONDS + 1 # after the pause it tries again (the owner may have added the bot meanwhile) client.fail_send = None rep.submit("third:", "ValueError: 3") await drain(rep) assert client.texts == ["third:\n\nValueError: 3"] await rep.stop() asyncio.run(go()) def test_other_sending_problems_do_not_silence_it(): async def go(): client = FakeSender() client.fail_send = RuntimeError("temporary network trouble") rep = reporter(client) rep.start() rep.submit("first:", "ValueError: 1") await drain(rep) client.fail_send = None rep.submit("second:", "ValueError: 2") await drain(rep) assert client.texts == ["second:\n\nValueError: 2"] await rep.stop() asyncio.run(go()) def test_a_chat_the_bot_is_not_in_is_noticed_at_start_up(): async def go(): rep = reporter(FakeSender(member=False)) problem = await rep.check() assert "ValueError" in problem and "add the bot to that chat" in problem good = reporter(FakeSender()) assert await good.check() is None assert await reporter(FakeSender(), chat_id=None).check() is None asyncio.run(go()) def test_switched_off(): async def go(): client = FakeSender() rep = reporter(client, chat_id=None) assert not rep.enabled rep.start() rep.submit("x:", "y") await rep.stop() assert client.sent == [] and client.lookups == [] and rep._task is None asyncio.run(go()) def test_submitting_from_another_thread_is_safe(): async def go(): client = FakeSender() rep = reporter(client) rep.start() t = threading.Thread(target=lambda: rep.submit("from a thread:", "ValueError: threaded")) t.start() t.join() await asyncio.sleep(0.05) await drain(rep) assert client.texts == ["from a thread:\n\nValueError: threaded"] # and before the reporter runs, or after it has stopped, nothing breaks await rep.stop() rep.submit("late:", "x") reporter(FakeSender()).submit("never started:", "x") asyncio.run(go()) def test_stop_lets_queued_reports_go_out(): async def go(): client = FakeSender() rep = reporter(client) rep.start() rep.submit("last words:", "ValueError: bye") await rep.stop() assert client.texts == ["last words:\n\nValueError: bye"] asyncio.run(go()) def test_the_peer_is_looked_up_once(): async def go(): client = FakeSender() rep = reporter(client) rep.start() for i in range(3): rep.submit(f"e{i}:", f"ValueError: {i}") await drain(rep) assert len(client.sent) == 3 and client.lookups == [CHAT] await rep.stop() asyncio.run(go()) @pytest.mark.parametrize("raw,label", [("Task-12", ""), ("", ""), ("sender", "sender")]) def test_task_labels(raw, label): task = SimpleNamespace(get_name=lambda: raw) assert errorlog._task_label(task) == label assert errorlog._task_label(None) == ""