diff --git a/README.md b/README.md index dcbdb58..4f4ef1c 100644 --- a/README.md +++ b/README.md @@ -44,9 +44,10 @@ The state and caches go in `/data` (its `DATA_DIR`), here a named volume. A host | `CHART_ALL_FEELS_LIKE=on` | optional: "weather all week" (every reading, a panel each, sent with just its title; UV is left out as it has the same shape as solar) also draws the feels-like panel; off by default, as it nearly repeats temperature. Naming either ("plot feels like", "plot solar and uv") always works | | `TUYA_DEVICE_ID`, `TUYA_CLIENT_ID`, `TUYA_CLIENT_SECRET` | enables the irrigation controller (a Tuya smart irrigation timer, through the Tuya cloud API): an Irrigation button in private chats (it replaces Wind) with its status and buttons to water for 5 to 30 minutes or switch the valve off, pause for 24 to 72 hours (the Pause button becomes Unpause while paused), refresh, and an Alerts menu to turn the chat's irrigation battery and irrigation pause alerts on or off (or type irrigation, water, tap or sprinkler); a daily check at 18:00 that delays it 24 hours when more than 1 mm fell in the last 24 hours or Open-Meteo gives today or tomorrow a 50% or better chance of 1 mm (needs Ecowitt and `FORECAST=on` for each half); an "irrigation pause" alert when it does, and an "irrigation battery" alert below 5%. `TUYA_BASE_URL` (default `https://openapi.tuyaeu.com`, the EU data centre) and `IRRIGATION_CHECK_HOUR` (default `18`) are optional | | `CHART_ALL_VPD=on` | optional: "weather all week" also draws the vapour pressure deficit panel; off by default, as it is temperature and humidity combined (the station reports it for the outdoor sensor only). Naming it ("plot vpd") always works | -| `TELEGRAM_PRELOAD_CHAT` | optional: a chat id (negative for a group or channel) the bot silently uploads charts to ahead of need. With it set, each chart sent with period buttons has its other periods drawn and uploaded there in the background (one at a time, never while a question is being answered), so pressing a period button edits the message with Telegram's copy and uploads nothing. A chart uploaded this way is used for 30 minutes, then drawn afresh. The bot must be able to post in that chat; the uploaded messages are left there. Unset: off | +| `TELEGRAM_PRELOAD_CHAT` | optional: a chat id (negative for a group or channel) the bot silently uploads charts to ahead of need. With it set, each chart sent with period buttons has its other periods drawn and uploaded there in the background, each on its own the moment it is drawn, starting as soon as the chart is sent and whatever else is being answered, so pressing a period button edits the message with Telegram's copy and uploads nothing. A chart uploaded this way is used for 30 minutes, then drawn afresh. The bot must be able to post in that chat; the uploaded messages are left there. If Telegram refuses an upload (the bot can't post there) none is tried again until a restart; a flood limit or a timeout only skips that photo. Unset: off | | `ANTISPIKE_REQUIRE_CONSECUTIVE` | optional: how many readings in a row a rise of the particles (PM1, PM2.5, PM10) needs to count as the air rather than a glitch of the sensor. Default `2`: a single-reading spike (at least 2.5 times, and 5 µg/m³ above, the readings either side) is left out of PM charts and of every air figure (highs, lows, averages, days over a limit), and the unhealthy-air alert counts a check only when the sensor's last 2 readings are all over the mask level. `3` also drops two-reading spikes, and so on; `1` or `off` turns the rule off. The live "air now" reading and the "safe again" check are unchanged | | `LOG_WIDTH` | optional: the most characters of a log line, cut with an ellipsis (…); `0` cuts none. Default 71. Every INFO line obeys it; a `WARN` or `ERROR` entry is never cut (a warning is printed as `WARN`); a request, chat message, reply or alert is also put on one line, and the startup "Alerts:" list wraps at it (at 90 when `0`) | +| `LOG_LEVEL` | optional: `DEBUG`, `INFO` (default), `WARNING` or `ERROR`. `DEBUG` adds the bot's own debug lines (the chart timings, charts it couldn't draw ahead); the libraries stay at their usual level. | ## Layout @@ -96,7 +97,7 @@ Both are off by default. They are websites, not APIs (the pollen page is parsed) model is called once, at the end, just to word the answer. - Recent readings are kept in memory, refreshed every minute (the weather station) and every 4 minutes (the air sensor); a question that may need them starts a refresh as it arrives (a chart made in code doesn't: it reads just what it needs). A question never waits for a refresh in flight when the cache and memory already hold what it needs, and its own Ecowitt requests go before the background ones. - The chart buttons' charts are drawn ahead every 5 minutes, one at a time and never while a question is being answered: a press is sent the one drawn in the last 5½ minutes at once (its write-up kept in the chat's memory, as for one drawn on the spot); an alert's chart is still drawn when it goes out, so it shows the reading the alert is about. A chart is uploaded once: sending it again (to the next chat an alert goes to, toggling back to a period drawn lately, the next press of a button) uses Telegram's copy. -- Each chart reply logs where its time went: `Chart ms: data 12, calc 6, draw 112, PNG 41 (22 KB), send 812`, or `Chart ms: drawn 40s ago, send 210 (Telegram's copy)` for one drawn ahead. +- Each chart reply logs (at DEBUG) where its time went: `Chart ms: data 12, calc 6, draw 112, PNG 41 (22 KB), send 812`, or `Chart ms: drawn 40s ago, send 210 (Telegram's copy)` for one drawn ahead. - The whole history of both sensors is kept in SQLite (`ecowitt_cache.sqlite`, `airgradient_cache.sqlite`): a background archive copies every Ecowitt cycle (5-minute, 30-minute, 4-hour, daily) before Ecowitt expires it, and backfills AirGradient day by day to where the sensor's diff --git a/ecobot.py b/ecobot.py index aa35baf..90132ac 100644 --- a/ecobot.py +++ b/ecobot.py @@ -44,6 +44,10 @@ logging.basicConfig(level=logging.INFO, handlers=[_handler]) logging.getLogger("httpx").setLevel(logging.WARNING) logging.getLogger("telegram.ext.Application").setLevel(logging.WARNING) # "Application started" etc. +_level = os.environ.get("LOG_LEVEL", "INFO").strip().upper() # LOG_LEVEL: DEBUG shows the bot's own debug lines (chart timings...), not the libraries' +if _level in ("DEBUG", "WARNING", "ERROR"): + for _name in ("ecobot", "lib"): + logging.getLogger(_name).setLevel(_level) log = logging.getLogger("ecobot") diff --git a/lib/bot.py b/lib/bot.py index a8ac48c..d1e16cc 100644 --- a/lib/bot.py +++ b/lib/bot.py @@ -17,7 +17,7 @@ from telegram import InputMediaPhoto, Message, ReplyKeyboardRemove, Update from telegram.constants import ChatAction, ChatType -from telegram.error import BadRequest, ChatMigrated, Forbidden, NetworkError, TelegramError +from telegram.error import BadRequest, ChatMigrated, Forbidden, NetworkError, RetryAfter, TelegramError, TimedOut from telegram.ext import CallbackQueryHandler, ChatMemberHandler, CommandHandler, ContextTypes, MessageHandler, filters from . import intent, periods, prompt, report, report_menu, templates @@ -246,13 +246,13 @@ def __init__(self, cfg: Config, agent: Agent, sources: list, state: AlertState | self.chats: dict[tuple, ChatState] = defaultdict(ChatState) self.by_name = {s.name: s for s in sources} self.images = periods.ImageCache() # charts drawn lately, so toggling the period buttons is instant (and the buttons' drawn ahead) - self.answering = 0 # questions being answered right now: charts are drawn ahead only when there are none + self.answering = 0 # questions being answered right now: the button charts are drawn ahead (predraw) only when there are none self.idle = asyncio.Event() self.idle.set() self.predrawn = False # the first round of charts drawn ahead has been logged self.predraw_failing: set[str] = set() # button charts that couldn't be drawn ahead (said once, until they can again) self.preloading: set[str] = set() # questions whose other periods are being uploaded (TELEGRAM_PRELOAD_CHAT) - self.preload_off = False # Telegram refused an upload to that chat: no more are tried until restart + self.preload_off = False # Telegram refused an upload to that chat (not a flood limit or a timeout): no more are tried until restart self.background: set[asyncio.Task] = set() # tasks running on their own, kept so they aren't dropped self.charted = periods.Charted(state.charts if state else None, state.save if state else None) # the question behind each chart sent (kept across restarts) @@ -622,7 +622,7 @@ async def on_period_button(self, update: Update, context: ContextTypes.DEFAULT_T self.images.sent(key, await message.edit_media(InputMediaPhoto(photo, caption=title or None), reply_markup=periods.keyboard(days))) self.charted.remember(message.chat_id, message.message_id, asked) self.preload_soon(context.bot, asked) - log.info("Period button: cached chart sent in %.0f ms%s", (time.monotonic() - began) * 1000, + log.debug("Period button: cached chart sent in %.0f ms%s", (time.monotonic() - began) * 1000, " (Telegram's copy)" if isinstance(photo, str) else "") return except TelegramError as e: @@ -861,38 +861,46 @@ def preload_soon(self, bot, question: str): async def preload(self, bot, chat: int, question: str): """Upload (silently, to `chat`) the chart for each other period of `question`, so a press of a period button edits the message by - Telegram's copy and uploads nothing. One at a time and never while a question is being answered.""" - started, done = time.monotonic(), [] + Telegram's copy and uploads nothing. Nothing holds it back: each period is drawn and uploaded on its own, the moment it can be, + whatever else is being answered.""" + started, done, skipped = time.monotonic(), set(), [] try: - for days in periods.PERIODS: - await self.idle.wait() - now = now_local(self.cfg.tz) - if days == intent.period_days(question, now): - continue - asked = intent.with_period(question, days, now) - if self.images.has_copy(self.images.key(asked, days, now)): - continue + now = now_local(self.cfg.tz) + own = intent.period_days(question, now) + asked = {days: intent.with_period(question, days, now) for days in periods.PERIODS if days != own} + asked = {days: text for days, text in asked.items() if not self.images.has_copy(self.images.key(text, days, now))} + + async def upload(days, text): try: - drawn = await self._draw_ahead(asked, now) + drawn = await self._draw_ahead(text, now) except Exception as e: - log.debug("Couldn't draw %r to preload: %s: %s", asked, type(e).__name__, e) - continue + log.debug("Couldn't draw %r to preload: %s: %s", text, type(e).__name__, e) + return if drawn is None: return key, png, title, caption = drawn self.images.put(key, png, title, caption, ttl=self.images.PRELOAD_TTL) + if self.preload_off: # an upload was refused meanwhile + return try: self.images.sent(key, await bot.send_photo(chat, png, caption=title or None, disable_notification=True)) + except (RetryAfter, TimedOut) as e: # Telegram's flood limit or a slow upload: a press uploads this one instead, and the next chart tries again + skipped.append(e) except TelegramError as e: - self.preload_off = True - log.warning("Couldn't upload to TELEGRAM_PRELOAD_CHAT %s (%s: %s); not preloading charts", chat, type(e).__name__, e) - return - done.append(periods.NAMES[days]) + if not self.preload_off: # said once, though every period's upload is refused + self.preload_off = True + log.warning("Couldn't upload to TELEGRAM_PRELOAD_CHAT %s (%s: %s); not preloading charts", chat, type(e).__name__, e) + else: + done.add(days) + + await asyncio.gather(*(upload(days, text) for days, text in asked.items())) + if skipped: + log.warning("TELEGRAM_PRELOAD_CHAT %s didn't take %d of the charts just now (%s: %s)", chat, len(skipped), type(skipped[0]).__name__, skipped[0]) + if done: + log.info("Preloaded %s of %r to chat %s in %.1fs", ", ".join(periods.NAMES[days] for days in periods.PERIODS if days in done), question, + chat, time.monotonic() - started, extra=QUOTES) finally: self.preloading.discard(question) - if done: - log.info("Preloaded %s of %r to chat %s in %.1fs", ", ".join(done), question, chat, time.monotonic() - started, - extra=QUOTES) async def predraw(self): """Draw the charts the buttons ask for ahead of the press: one pressed in the next ImageCache.FRESH seconds is sent at once. @@ -921,7 +929,7 @@ async def predraw(self): log.info("Button charts drawn ahead every %ds: %d in %.1fs", PREDRAW_SECONDS, len(done), time.monotonic() - started) async def respond(self, update: Update, context: ContextTypes.DEFAULT_TYPE, text: str, redraw: Message | None = None): - """Answer a question (_respond), counted while it runs: no chart is drawn ahead meanwhile.""" + """Answer a question (_respond), counted while it runs: predraw waits for it.""" self.answering += 1 self.idle.clear() try: @@ -1036,10 +1044,10 @@ async def _respond(self, update: Update, context: ContextTypes.DEFAULT_TYPE, tex titles=titles, period_row=row, sent_photo=sent_photo, bold_headings=ok and bool(read.report or read.lookup in ("pollen", "forecast"))) and bool(markup) # the refresh button is not the chat's keyboard if ready: - log.info("Chart ms: drawn %.0fs ago, send %.0f%s", self.images.age(ready), (time.monotonic() - began) * 1000, + log.debug("Chart ms: drawn %.0fs ago, send %.0f%s", self.images.age(ready), (time.monotonic() - began) * 1000, " (Telegram's copy)" if isinstance(drawn[0], str) else "") elif drawn: - log.info("Chart ms: %s", chart_times(turn.times, made, drawn, time.monotonic() - began)) + log.debug("Chart ms: %s", chart_times(turn.times, made, drawn, time.monotonic() - began)) if sent_photo: self.charted.remember(msg.chat_id, sent_photo[0].message_id, text) self.images.sent(kept, sent_photo[0]) diff --git a/tests/test_bot.py b/tests/test_bot.py index b4efff9..0ae83a5 100644 --- a/tests/test_bot.py +++ b/tests/test_bot.py @@ -367,7 +367,7 @@ async def reply_photo(photo, caption=None, **kw): async def send_chat_action(*a, **k): pass - with caplog.at_level("INFO"): + with caplog.at_level("DEBUG"): await Bot(NS(tz=TZ), Agent(), sources, None).respond(update, NS(bot=NS(send_chat_action=send_chat_action, id=99)), "Temperature chart 1d") await eco.close() diff --git a/tests/test_periods.py b/tests/test_periods.py index d87fadd..3b19450 100644 --- a/tests/test_periods.py +++ b/tests/test_periods.py @@ -275,18 +275,31 @@ async def test_charts_are_not_drawn_ahead_while_a_question_is_being_answered(mon def preloading_bot(monkeypatch, refuse=None, clock=None): - """A bot with TELEGRAM_PRELOAD_CHAT set, and the (chat, photo, silent) of every upload to it.""" - bot, uploads = make_bot(monkeypatch), [] + """A bot with TELEGRAM_PRELOAD_CHAT set, and the (chat, photo, silent) of every upload to it. The periods are uploaded side by side, + in no fixed order, so each period's picture is its question's words and its file id "file " and those words; context.refused.error + is what the uploads raise (none: they go through).""" + bot, uploads, refused = make_bot(monkeypatch), [], NS(error=refuse) bot.cfg = NS(tz=TZ, telegram_preload_chat=-1001) if clock: bot.images = periods.ImageCache(lambda: clock[0]) + draw = bot._draw_ahead + + async def draw_ahead(text, now): + key, _, title, caption = await draw(text, now) + return key, text.encode(), title, caption + bot._draw_ahead = draw_ahead async def send_photo(chat, photo, caption=None, disable_notification=False): - if refuse: - raise refuse + if refused.error: + raise refused.error uploads.append((chat, photo, disable_notification)) - return NS(photo=(NS(file_id="small"), NS(file_id=f"file {len(uploads)}"))) - return bot, uploads, NS(bot=NS(send_chat_action=send_chat_action, send_photo=send_photo, id=99)) + return NS(photo=(NS(file_id="small"), NS(file_id=f"file {photo.decode()}"))) + return bot, uploads, NS(bot=NS(send_chat_action=send_chat_action, send_photo=send_photo, id=99), refused=refused) + + +def uploads_of(*days): + """What the uploads to the preload chat are, in any order, when they are the Temperature charts of these periods.""" + return sorted((-1001, f"Temperature chart {d}d".encode(), True) for d in days) async def settle(bot): @@ -306,14 +319,14 @@ async def edit_media(media, reply_markup=None): await bot.respond(NS(effective_message=msg, effective_chat=msg.chat, effective_user=NS(username="rob", full_name="Rob")), context, "Temperature chart 7d") await settle(bot) - assert [(c, p, silent) for c, p, silent in uploads] == [(-1001, b"png", True)] * 4 # 1D, 1M, 3M, 1Y: not the 7D just sent + assert sorted(uploads) == uploads_of(1, 30, 90, 365) # 1D, 1M, 3M, 1Y: not the 7D just sent calls = len(bot.agent.tools.calls) async def answer(text=None): pass await bot.on_period_button(NS(callback_query=NS(data="pd:90", message=msg, answer=answer), effective_message=msg, effective_chat=msg.chat, effective_user=NS(username="rob", full_name="Rob")), context) - assert len(bot.agent.tools.calls) == calls and edits[0].startswith("file ") # Telegram's copy, no new question or upload + assert len(bot.agent.tools.calls) == calls and edits[0] == "file Temperature chart 90d" # Telegram's copy of the 3M, no new question or upload async def test_nothing_is_uploaded_ahead_without_the_setting_and_a_refused_upload_stops_it_with_one_warning(monkeypatch, caplog): @@ -330,7 +343,76 @@ async def test_nothing_is_uploaded_ahead_without_the_setting_and_a_refused_uploa await settle(bot) await bot.respond(pressed(bot, []), context, "Temperature chart 30d") await settle(bot) - assert [r for r in caplog.records if "TELEGRAM_PRELOAD_CHAT" in r.getMessage()].__len__() == 1 and uploads == [] + assert [r for r in caplog.records if "TELEGRAM_PRELOAD_CHAT" in r.getMessage()].__len__() == 1 and uploads == [] and bot.preload_off + + +async def test_a_flood_limit_or_a_timeout_skips_those_uploads_and_the_next_chart_uploads_again(monkeypatch, caplog): + import warnings + from telegram.error import RetryAfter, TimedOut + with warnings.catch_warnings(): + warnings.simplefilter("ignore") # python-telegram-bot 22 warns whenever it builds a RetryAfter + flood = RetryAfter(30) + bot, uploads, context = preloading_bot(monkeypatch) + for error, asked in ((flood, "Temperature chart 7d"), (TimedOut(), "Temperature chart 30d")): + context.refused.error = error + with caplog.at_level("WARNING"): + await bot.respond(pressed(bot, []), context, asked) + await settle(bot) + assert uploads == [] and not bot.preload_off + assert len([r for r in caplog.records if "TELEGRAM_PRELOAD_CHAT" in r.getMessage()]) == 2 # one a chart, though several uploads were skipped + context.refused.error = None + await bot.respond(pressed(bot, []), context, "Temperature chart 90d") + await settle(bot) + assert sorted(uploads) == uploads_of(1, 365) # the 7D and the 1M were sent as the questions' own charts + + +async def test_a_period_that_cannot_be_drawn_is_left_out_and_the_others_are_uploaded(monkeypatch): + bot, uploads, context = preloading_bot(monkeypatch) + draw = bot._draw_ahead + + async def draw_ahead(text, now): + if text.endswith("90d"): + raise ValueError("no readings") + return await draw(text, now) + bot._draw_ahead = draw_ahead + await bot.respond(pressed(bot, []), context, "Temperature chart 7d") + await settle(bot) + assert sorted(uploads) == uploads_of(1, 30, 365) + assert bot.images.has_copy(bot.images.key("Temperature chart 30d", 30, NOW)) and not bot.images.has_copy(bot.images.key("Temperature chart 90d", 90, NOW)) + + +async def test_charts_are_uploaded_ahead_at_once_even_while_a_question_is_being_answered(monkeypatch): + import asyncio + bot, uploads, context = preloading_bot(monkeypatch) + bot.answering = 1 + bot.idle.clear() + bot.preload_soon(context.bot, "Temperature chart 7d") + await asyncio.wait_for(settle(bot), 5) # it would wait for ever if it waited for the question + assert sorted(uploads) == uploads_of(1, 30, 90, 365) + + +async def test_each_period_is_uploaded_as_soon_as_it_is_drawn_not_when_the_slowest_is(monkeypatch): + import asyncio + bot, uploads, context = preloading_bot(monkeypatch) + slow, three, draw, send = asyncio.Event(), asyncio.Event(), bot._draw_ahead, context.bot.send_photo + + async def draw_ahead(text, now): + if text.endswith("chart 1d"): + await slow.wait() + return await draw(text, now) + + async def send_photo(chat, photo, **kw): + message = await send(chat, photo, **kw) + if len(uploads) == 3: + three.set() + return message + bot._draw_ahead, context.bot.send_photo = draw_ahead, send_photo + bot.preload_soon(context.bot, "Temperature chart 7d") + await asyncio.wait_for(three.wait(), 5) + assert sorted(uploads) == uploads_of(30, 90, 365) # the 1D, first in line, is still being drawn + slow.set() + await asyncio.wait_for(settle(bot), 5) + assert sorted(uploads) == uploads_of(1, 30, 90, 365) async def test_a_chart_uploaded_ahead_is_used_for_30_minutes_and_then_drawn_afresh(monkeypatch):