Re: [weewx-user] catching the 'why' of engine.py exiting

['John Kline' via weewx-user]

I *may* have found the regression. It’s new in beta3 and it’s a full table scan of the archive table on every report cycle. beta3 adds a local-AQI path to bin/user/new_belchertown.py. The core helper: def _archive_latest_numeric(archive_manager, column_name):     row = archive_manager.getSql(     f"SELECT dateTime, {column_name} FROM archive "     f"WHERE {column_name} IS NOT NULL "     "ORDER BY dateTime DESC LIMIT 1"     ) _archive_local_aqi_payload() calls it for pm2_5_aqi, and if that comes back empty, falls through to _archive_pm25_nowcast_payload(), which calls it again for pm2_5. Neither function exists in 2.0 — all of this is new. dateTime is the archive table’s INTEGER PRIMARY KEY, so SQLite walks backwards from the newest row. If the column has recent data it stops on the first row and costs nothing. If the column exists in the schema but is empty, SQLite has to read every row in the table to prove there’s no non-NULL value anywhere. That’s a full scan, disk-bound, holding a SQLite read lock for its entire duration — which is what blocks the archive writer and produces “database is locked”. It’s gated on aqi_enabled, which defaults to 0. Your log shows “Xweather AQI fallback cached to forecast.json”, so you have it on. I measured this on my own system — WeeWX 5.4.0, Pi 5, 785,666 archive records (~7.5 years), NVMe. Same query shape, comparing a populated column against an empty one: populated column (pm2_5):     0.001 s empty column (hail), warm:    0.219 s empty column (hail), cold:    1.120 s The cold number is after dropping caches. User CPU time is identical between the warm and cold runs, so the extra second is purely waiting on disk. Scaling to 13 years is roughly 1.75x my row count, so ~2 s per query cold, ~4 s for the pair. On slower storage — an ordinary SD card, where random page reads are an order of magnitude worse than NVMe — that could easily be 15-30 s per query. Two queries would confirm it on your database: .timer on SELECT dateTime, pm2_5_aqi FROM archive WHERE pm2_5_aqi IS NOT NULL ORDER BY dateTime DESC LIMIT 1; SELECT dateTime, pm2_5 FROM archive WHERE pm2_5 IS NOT NULL ORDER BY dateTime DESC LIMIT 1; A parse error means the column isn’t in your schema and that one is harmless. A fast result means the column has recent data. A slow result is the bug. BTW, storing pm2_5_aqi in the database is a guaranteed way to get the wrong answer for AQI.  AQI is defined as a formula to be applied to the average pm2.5 for any given time period.  It is NOT defined as the average of AQI calculations over said time period.  I had a recent discussion with a user of one of my air quality sensor extensions.  By adding AQI to the db, which he did, he was disabling the XType which comes with the weewx-purple, weewx-airlink and weewx-airgradient extensions that would properly calculate the AQI.  And it saved virtually no time in getting the wrong answer.  All of the time is the database access and it's doing the same accesses either way--one is getting AQI, the other pm2.5. On Aug 4, 2026, at 8:10 AM, John Kline <j...@johnkline.com> wrote:  If anyone wants to see where a report cycle is actually spending its time, py-spy will tell you without modifying anything. Install it into a throwaway venv and dump the running weewxd: python3 -m venv ~/pyspy-venv ~/pyspy-venv/bin/pip install py-spy pgrep -af weewxd sudo ~/pyspy-venv/bin/py-spy dump –pid <pid> It attaches to the live process, prints a stack for every thread, and detaches. No restart, no config change, no debug logging. I run weewx from a pip install, not in a container. My understanding is that under Docker you’d run py-spy on the host and point it at the host-side PID of the weewxd process rather than the one you see inside the container, and that there may be a ptrace permission to sort out. I haven’t done it, so someone who uses containers should confirm. Here’s one from my system (WeeWX 5.4.0, LiveSeasons (personal skin), Pi 5), taken during a report cycle. I’ve cut the idle service threads: Thread 1767872 (idle): “MainThread” read (serial/serialposix.py:565) … [seven idle service threads elided] Thread 379811 (active): “ReportThread” execute (weedb/sqlite.py:249) guarded_fn (weedb/sqlite.py:38) getSql (weewx/manager.py:586) firstGoodStamp (weewx/manager.py:326) create_sync (weewx/manager.py:303) sync (weewx/manager.py:307) init (weewx/manager.py:142) open (weewx/manager.py:187) open_manager (weewx/manager.py:921) getLatestForecastRows (user/nws.py:1702) alerts (user/nws.py:1620) respond (cheetah…alerts_inc….py:297) handleCheetahInclude (Cheetah/Template.py:1712) respond (cheetah_…alerts_html_tmpl….py:167) generate (weewx/cheetahgenerator.py:335) generate (weewx/cheetahgenerator.py:226) generate (weewx/cheetahgenerator.py:226) run (weewx/cheetahgenerator.py:166) start (weewx/reportengine.py:482) run (weewx/reportengine.py:252) _bootstrap_inner (threading.py:1043) _bootstrap (threading.py:1014) The report thread is named ReportThread, so it’s easy to find in the output. Two things this makes visible. First, exactly what the cycle is doing at that instant — which generator, which template, which query, right down to the line. Second — and more to the point of this thread — it settles the concurrency question directly. Every thread in the process is listed, so if two report cycles are running at once, you get two entries with two distinct thread IDs. One dump answers it. No inferring from CPU load, no relying on what does or doesn’t get logged. For what it’s worth, I don’t think a second report thread is being launched in the log posted here. weewx will launch one alongside a running cycle, but only once the existing thread has been alive for max_wait seconds (600 by default). In that log the report thread was about 300 seconds old when the process took the database-locked exception and shut down, and the restart resets the launch time — so the 600 s threshold never gets close. That’s also why changing max_wait had no effect: neither branch of that test is being reached. On Aug 4, 2026, at 6:26 AM, John Kline <j...@johnkline.com> wrote:  What did you see that told you it had no effect — a second report thread launching, or the database is locked crashes continuing? If it’s the crashes, that’s expected. max_wait only suppresses the second launch; the first report keeps holding the database either way, which is what takes weewx down. If it’s an actual second thread launching, I’d want to see it — with max_wait at 31.7 years. Worth confirming the setting landed in [StdReport] and that weewx was restarted after the change. On Aug 4, 2026, at 6:11 AM, t...@tom.org <t...@tom.org> wrote: Yes, John, except changing max_wait had no effect in my case. On Tuesday, August 4, 2026 at 6:10:37 AM UTC-7 John Kline wrote: One more thing, remembering that the OP is NOT focused on the database lock; but rather, another report cycle starting, adding [StdReport] max_wait = 999999999 will give the OP what he is asking for. On Aug 4, 2026, at 6:03 AM, John Kline <jo...@johnkline.com> wrote:  Small correction first: I didn’t show that. The version-logged-once-per-process point is your reading of the log, not something I demonstrated — and I don’t think the log can settle it either way. That engine started at 09:56 and died at 10:05:23, so it only ever got one report launch. A single version 2.1beta3 line is equally consistent with “logs once per process” and with “only one cycle ran.” You may well be right about the skin’s logging behavior, but that log isn’t evidence for it. On the substance, you’re right that a successful launch is silent. launch_report_thread() logs nothing on the happy path, so a report cycle can start with no trace in the weewx log. But a blocked launch is not silent:     log.info("Launch of report thread aborted: existing report thread still running") Which leaves two possibilities: POST_LOOP never fired, because the OperationalError killed the main loop first — or the 10:00 cycle had already finished and a fresh one launched silently. The second requires the 10:00 cycle to have completed without ever logging Generated N files, which I’d want evidence for. On CPU: a busy CPU doesn’t distinguish a second run from the first one still grinding. The orphaned thread from 10:00 explains it by itself — nothing joined it, and self.thread gets reassigned on the next launch, so it just keeps running untracked. py-spy dump on the running process lists every thread with its stack. One StdReportEngine or two stops being a matter of interpretation at that point. On Aug 4, 2026, at 5:51 AM, t...@tom.org <t...@tom.org> wrote: Yes this is the behavior I have seen (Matthew is not hallucinating!) for a long time and it is not happening here. Also, John showed in the logs that the extension name and version are only printed to the console on the first run. Subsequent runs are silent until the message about how many files were generated, so while it looks like there is no evidence of a rogue report run, it's happening silently (and you can see it on CPU too). On Tuesday, August 4, 2026 at 5:40:37 AM UTC-7 John Kline wrote: The code is still there. max_wait defaults to 60s, so it will start another report cycle after 10m (assuming max_wait is overrridden somewher). def launch_report_thread(self, _event): """Called after the packet LOOP. Processes any new data.""" import weewx.reportengine # Do not launch the reporting thread if an old one is still alive. # To guard against a zombie thread (alive, but doing nothing) launch # anyway if enough time has passed. if self.thread and self.thread.is_alive(): thread_age = time.time() - self.launch_time if thread_age < self.max_wait: log.info("Launch of report thread aborted: existing report thread still running") return else: log.warning("Previous report thread has been running" " %s seconds. Launching report thread anyway.", thread_age) try: self.thread = weewx.reportengine.StdReportEngine(self.config_dict, self.engine.stn_info, self.record, first_run=not self.launch_time) self.thread.start() self.launch_time = time.time() except threading.ThreadError: log.error("Unable to launch report thread.") self.thread = None > On Aug 4, 2026, at 5:24 AM, matthew wall <mwall...@gmail.com> wrote: > > i might be hallucinating, but i remember at one point the code that starts reports would check to see if a report was still running. if the report was still running, it would skip that report and go to the next, with a log entry that the report was skipped. > > a quick scan of reportengine.py does not show any of that behavior, so i must be remembering logic from a previous implementation or something that never made it to master. > > a per-report mutex/lock could be done in reportengine.py. but it might be better to do it within each report, since the report has more detail (and could thus provide better logs) about what is happening. > > i suppose that starting a thread for each report could lead to much complexity if reports try to write to the database, not just read from it > > there have *always* been issues with shutting down the reporting thread. if something in the report thread has a unresponsive file handle open (e.g., slow nfs link) or a network socket open, then the thread does not shut down immediately when the engine does a shutdown. > > m > > -- > You received this message because you are subscribed to the Google Groups "weewx-user" group. > To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com. > To view this discussion visit https://groups.google.com/d/msgid/weewx-user/C69E9E4C-0B2F-44E8-B437-75990351E842%40gmail.com. -- You received this message because you are subscribed to the Google Groups "weewx-user" group. To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com. To view this discussion visit https://groups.google.com/d/msgid/weewx-user/d8fc89c7-0550-43b0-aaed-9a7dfb8f2711n%40googlegroups.com. -- You received this message because you are subscribed to the Google Groups "weewx-user" group. To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscr...@googlegroups.com. To view this discussion visit https://groups.google.com/d/msgid/weewx-user/72d6e8b1-5f4f-4adc-ae77-2a1ceada1276n%40googlegroups.com. -- You received this message because you are subscribed to the Google Groups "weewx-user" group. To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscr...@googlegroups.com. To view this discussion visit https://groups.google.com/d/msgid/weewx-user/7F373317-AC5E-471F-B6D9-1949B69F8031%40johnkline.com.