Preupload without waiting, chart timings at DEBUG, LOG_LEVEL

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

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")
 
 

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])

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()