From 595eef191591bd44b4e7c674fd91ec5ff1814221 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 29 Oct 2026 22:01:55 +0000 Subject: [PATCH 1/4] Log lines carry their syslog priority under journald, so journalctl colours and filters by level Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_01JVEkZofdPjQ4jtXFKipeUX --- doc/configuration.md | 2 +- lib/log.py | 14 ++++++++++++-- tests/test_edges.py | 16 ++++++++++++++-- 3 files changed, 27 insertions(+), 5 deletions(-) diff --git a/doc/configuration.md b/doc/configuration.md index b48653c6..7a09082e 100644 --- a/doc/configuration.md +++ b/doc/configuration.md @@ -80,7 +80,7 @@ The administrators of the chat a person is in are admins there with no setting: | `cache_seconds` | `21600` | Cache lifetime in seconds (6 hours) | | `performance_cache_seconds` | `2400` | Cache lifetime of Sharesight performance reports in seconds: longer than the 30 minutes between `sharesight_warm` runs, so the holdings never run out | | `http_timeout` | `18` | Seconds to wait on outbound HTTP requests | -| `log_level` | `INFO` | What the log shows: that level and those above it, syslog style. `ERROR`: what failed and was lost (a message not sent); `WARN`: what failed and was got over (a retry, a fallback, a request refused); `INFO`: what finbot does (each message sent, each job run, each request sent, each request refused); `DEBUG`: the routine of a button press too (the press, its acknowledgement, the message edited in place), each request answered with success, and each cache miss, hit and write. Replaces `debug` | +| `log_level` | `INFO` | What the log shows: that level and those above it, syslog style. `ERROR`: what failed and was lost (a message not sent); `WARN`: what failed and was got over (a retry, a fallback, a request refused); `INFO`: what finbot does (each message sent, each job run, each request sent, each request refused); `DEBUG`: the routine of a button press too (the press, its acknowledgement, the message edited in place), each request answered with success, and each cache miss, hit and write. Replaces `debug`. Under systemd each line carries its syslog priority (error, warning, info, debug), so `journalctl` colours it and `journalctl -p warning` filters by it | | `log_width` | `71` | The most characters of a log line that can run long: a longer one is cut there, ending in `…`. That is each request's line (its method and URL) and each chat message's (who sent what, in which network). A message of several lines is logged on one line, its line breaks spaces. `0`: no line is cut | | `print_headers` | `False` | Log inbound request headers | diff --git a/lib/log.py b/lib/log.py index 0c9d7026..246034d2 100644 --- a/lib/log.py +++ b/lib/log.py @@ -1,12 +1,16 @@ """The log, syslog style: each line has a level, ERROR, WARN, INFO or DEBUG, and goes to stderr (which systemd and Docker take to the journal) when the log_level setting lets it in: that level and those above it, so ERROR always -does. Each takes print()'s arguments. A line that can run long (a request's URL, a chat message) goes through cut(), +does. Each takes print()'s arguments. Under journald (JOURNAL_STREAM is set) a line starts with its syslog priority, +<3> to <7>, which journald takes off and files the line under, so journalctl colours and filters (-p) by it; anywhere +else a line has no prefix. A line that can run long (a request's URL, a chat message) goes through cut(), which puts it on one line within the log_width setting.""" +import os import sys from lib import config LEVELS = config.LOG_LEVELS # ERROR WARN INFO DEBUG, the most severe first +PRIORITIES = {'ERROR': 3, 'WARN': 4, 'INFO': 6, 'DEBUG': 7} # syslog's err, warning, info and debug def enabled(level): @@ -14,10 +18,16 @@ def enabled(level): return LEVELS.index(level) <= LEVELS.index(config.settings.log_level) +def prefix(level): + """What starts a line of this level: its syslog priority, as journald reads it, under journald, else nothing.""" + return f'<{PRIORITIES[level]}>' if os.environ.get('JOURNAL_STREAM') else '' + + def write(level, parts, options): """A line of these parts (and print()'s options) at this level, if log_level lets it in.""" if enabled(level): - print(*parts, file=sys.stderr, **options) + sep = str(options.pop('sep', None) or ' ') + print(prefix(level) + sep.join(str(part) for part in parts), file=sys.stderr, **options) def cut(text): diff --git a/tests/test_edges.py b/tests/test_edges.py index 7aeb52a2..4f4c657c 100644 --- a/tests/test_edges.py +++ b/tests/test_edges.py @@ -1,6 +1,6 @@ """Failure and no-data scenarios: empty or broken upstream data, bad arguments, unknown portfolios, secrets kept out of logs, and the bot's signals.""" -import contextlib, io, os, re, signal, subprocess, sys, tempfile, threading, time, unittest +import contextlib, io, os, re, signal, subprocess, sys, tempfile, threading, time, unittest, unittest.mock from pathlib import Path from tests.common import * from lib import log @@ -424,6 +424,18 @@ def each(): with self.subTest(log_level=level): self.assertEqual(self.logged(level, each), list(shown)) + def test_under_journald_each_line_starts_with_its_syslog_priority(self): + """With JOURNAL_STREAM set, a line starts with <3> (error), <4> (warning), <6> (info) or <7> (debug), which + journald takes off and files the line under; a line's print() separator is kept.""" + def each(): + """A line at each level.""" + log.error('e', 'x') + log.warn('w', 'x', sep='-') + log.info('i') + log.debug('d') + with unittest.mock.patch.dict(os.environ, {'JOURNAL_STREAM': '8:1234'}): + self.assertEqual(self.logged('DEBUG', each), ['<3>e x', '<4>w-x', '<6>i', '<7>d']) + def test_a_cache_miss_hit_or_write_is_debug(self): """A cache miss (of a file not there, or too old), a hit, and the write after a miss are logged at DEBUG only: at INFO, the request a miss sends is the line.""" @@ -525,7 +537,7 @@ def test_a_hosts_connections_idle_too_long_are_dropped_before_the_next_request(s clock, cleared = [1000.0], [] adapter = type('Adapter', (), {'poolmanager': type('Pools', (), {'clear': lambda self: cleared.append(1)})()})() with mock.patch.object(net.time, 'monotonic', lambda: clock[0]), mock.patch.object(net.session, 'get_adapter', - lambda url: adapter), mock.patch.dict(net._used, clear=True): + lambda url: adapter), unittest.mock.patch.dict(net._used, clear=True): net.fresh('https://api.telegram.org/bot1/sendPhoto') # the first use of a host clock[0] += net.IDLE_SECONDS - 1 net.fresh('https://api.telegram.org/bot1/sendMessage') # used a moment ago From 82eac85078d72ab668e2bcf411c50c3ab775717c Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 29 Oct 2026 22:12:09 +0000 Subject: [PATCH 2/4] Default jobs: weekly on Saturday, monthly and quarterly on the 1st at 9:00, earnings monthly, performance 1w/1m/3m; no podcast, bi-annual or annual defaults Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_01JVEkZofdPjQ4jtXFKipeUX --- doc/scheduling.md | 44 ++++++++++++++++++----------------------- lib/catalog.py | 27 ++++++++++--------------- tests/test_schedule.py | 23 +++++++++------------ tests/test_scheduler.py | 24 +++++++++++----------- 4 files changed, 50 insertions(+), 68 deletions(-) diff --git a/doc/scheduling.md b/doc/scheduling.md index 9a47c3f3..db07375d 100644 --- a/doc/scheduling.md +++ b/doc/scheduling.md @@ -107,7 +107,7 @@ The commands that change something (`watchlist`, `plan`, `jobs`) are no jobs, an earnings, dividends, session and premarket are run by their reports above. The period of `performance` and `movers` follows how often the job runs: weekly covers 7 days, monthly 30, quarterly -90, bi-annual 180 and annual 365, and a daily `movers` is the day's moves. A number given (`movers 30 weekly`) is used +90, bi-annual 180 and annual 365 (`performance` shows them as 1w, 1m, 3m), and a daily `movers` is the day's moves. A number given (`movers 30 weekly`) is used instead. A **reminder** posts its text as it is: @@ -134,35 +134,29 @@ move as either side's daylight saving changes. | 6 | movers close HK | weekdays at 4:30pm Hong Kong (7:30pm local) | | 7 | movers close UK | weekdays at 5:00pm London (3:00am local, Tue–Sat) | | 8 | movers close US | weekdays at 4:30pm New York (7:30am local, Tue–Sat) | -| 9 | rating | Tue–Sat at 8:30am Sydney | -| 10 | milestone | Tue–Sat at 8:30am Sydney | -| 11 | podcasts Money Cafe | hourly at :01, weekdays 10am–9pm Sydney | -| 12 | podcasts Stocktake | hourly at :01, weekdays 10am–9pm Sydney | -| 13 | earnings | weekly, Sundays at 8:30am Sydney | -| 14 | shorts | weekly, Sundays at 8:30am Sydney | -| 15 | performance | weekly, Sundays at 8:30am Sydney | -| 16 | movers | weekly, Sundays at 8:30am Sydney | -| 17 | performance | monthly, the 2nd at 8:30am Sydney | -| 18 | movers | monthly, the 2nd at 8:30am Sydney | -| 19 | performance | quarterly, 2 Jan/Apr/Jul/Oct at 8:30am Sydney | -| 20 | movers | quarterly, 2 Jan/Apr/Jul/Oct at 8:30am Sydney | -| 21 | performance | bi-annual, 2 Jan and 2 Jul at 8:30am Sydney | -| 22 | movers | bi-annual, 2 Jan and 2 Jul at 8:30am Sydney | -| 23 | performance | annual, 2 Jan at 8:30am Sydney | -| 24 | movers | annual, 2 Jan at 8:30am Sydney | -| 25 | 🥳 Happy EOFY 🇬🇧 🇭🇰 🇮🇳 🇰🇷 🇳🇿 🇯🇵 🇿🇦 | annual, 31 Mar at 8:30am Sydney | -| 26 | 💸 Realise capital gains/losses by EOFY June 30 (AU) | annual, 23 Jun at 8:30am Sydney | -| 27 | 🥳 Happy EOFY 🇦🇺 🇧🇩 🇪🇬 🇪🇹 🇰🇪 🇳🇵 🇵🇰 | annual, 30 Jun at 8:30am Sydney | -| 28 | ✍️ Submit 'Notice of Intent to Claim' … (AU) | annual, 7 Jul at 8:30am Sydney | -| 29 | finbot's birthday | annual, 18 Aug at 8:30am Sydney | -| 30 | 😓 Self-service individual tax returns are due Oct 31 (AU) | annual, 25 Oct at 8:30am Sydney | -| 31 | 😰 Self-service individual tax returns are due today (AU) | annual, 31 Oct at 8:30am Sydney | +| 9 | rating | Tue–Sat at 9:00am Sydney | +| 10 | milestone | Tue–Sat at 9:00am Sydney | +| 11 | earnings | monthly, the 1st at 9:00am Sydney | +| 12 | shorts | weekly, Saturdays at 9:00am Sydney | +| 13 | performance 1w | weekly, Saturdays at 9:00am Sydney | +| 14 | movers | weekly, Saturdays at 9:00am Sydney | +| 15 | performance 1m | monthly, the 1st at 9:00am Sydney | +| 16 | movers | monthly, the 1st at 9:00am Sydney | +| 17 | performance 3m | quarterly, 1 Jan/Apr/Jul/Oct at 9:00am Sydney | +| 18 | movers | quarterly, 1 Jan/Apr/Jul/Oct at 9:00am Sydney | +| 19 | 🥳 Happy EOFY 🇬🇧 🇭🇰 🇮🇳 🇰🇷 🇳🇿 🇯🇵 🇿🇦 | annual, 31 Mar at 8:30am Sydney | +| 20 | 💸 Realise capital gains/losses by EOFY June 30 (AU) | annual, 23 Jun at 8:30am Sydney | +| 21 | 🥳 Happy EOFY 🇦🇺 🇧🇩 🇪🇬 🇪🇹 🇰🇪 🇳🇵 🇵🇰 | annual, 30 Jun at 8:30am Sydney | +| 22 | ✍️ Submit 'Notice of Intent to Claim' … (AU) | annual, 7 Jul at 8:30am Sydney | +| 23 | finbot's birthday | annual, 18 Aug at 8:30am Sydney | +| 24 | 😓 Self-service individual tax returns are due Oct 31 (AU) | annual, 25 Oct at 8:30am Sydney | +| 25 | 😰 Self-service individual tax returns are due today (AU) | annual, 31 Oct at 8:30am Sydney | * **Market reports run in their market's zone**, so they keep to its session through its daylight saving: * pre-market US at 7:15am New York; * mid-session about halfway through: 1:00pm Sydney for the ASX, 12:45pm New York for the NYSE; * the close 30 minutes after it: 4:30pm Sydney for the ASX, 4:30pm Hong Kong, 5:00pm London and 4:30pm New York. -* **The reminders (from 25 on)** marked (AU) are default jobs only where the `country_code` setting is `AU`. A chat +* **The reminders (from 19 on)** marked (AU) are default jobs only where the `country_code` setting is `AU`. A chat adds its own with `/jobs add reminder` ([A job in English](#a-job-in-english)). * **trades and performance** are default jobs only where Sharesight is set up (see [Configuration](configuration.md#sharesight)). diff --git a/lib/catalog.py b/lib/catalog.py index deb3e583..778e3bd4 100644 --- a/lib/catalog.py +++ b/lib/catalog.py @@ -11,15 +11,13 @@ from lib import when SYDNEY, NEW_YORK, HONG_KONG, LONDON = 'Australia/Sydney', 'America/New_York', 'Asia/Hong_Kong', 'Europe/London' -MORNING = '08:30' # by Sydney's clock: the weekly and longer reports, and the reminders +MORNING = '09:00' # by Sydney's clock: the weekly and longer reports +REMINDERS = '08:30' # by Sydney's clock: the reminders TUE_SAT = ['tue', 'wed', 'thu', 'fri', 'sat'] # the mornings after a US session SHARESIGHT = ('trades', 'performance', 'holdings', 'treemap', 'who') # the actions that report on Sharesight PERIODIC = ('performance', 'movers') # the reports whose period follows how often they run PERIOD_DAYS = {'daily': 1, 'weekdays': 1, 'weekly': 7, 'monthly': 30, 'quarterly': 90, 'bi-annual': 180, 'annual': 365} -MONEY_CAFE = ('https://www.omnycontent.com/d/playlist/b034de0e-930d-434b-9822-a7140060b2c0/' - '95d715e5-10a7-4e54-b114-a9b4001be172/c47481a8-e548-4c2b-8592-ad48003dc9c2/podcast.rss') -STOCKTAKE = ('https://www.omnycontent.com/d/playlist/b034de0e-930d-434b-9822-a7140060b2c0/' - '087f773e-34f7-45fb-a4f2-a78b000c6495/b9e412ea-f1ee-40db-a0f8-aaf5005d790d/podcast.rss') +PERIOD_NAMES = {7: '1w', 30: '1m', 90: '3m', 180: '6m', 365: '1y'} # how performance's period is written @dataclasses.dataclass(frozen=True) @@ -42,7 +40,7 @@ def period_args(action, schedule): if action == 'movers': return ['interday'] if days in (None, 1) else [str(days)] if action == 'performance': - return [] if days is None else [str(days)] + return [] if days is None else [PERIOD_NAMES.get(days, str(days))] return [] @@ -66,7 +64,7 @@ def message(key, date, lines, country=None, name=None): that country's flag for {flag} (markets.flag); named after its first line unless it has a name.""" return Item(key, name or message_name(lines, country), 'message', tuple(line.replace('{flag}', markets.flag(country or '')) for line in lines), - at({'day': int(date[3:]), 'months': [int(date[:2])]}), country) + at({'day': int(date[3:]), 'months': [int(date[:2])]}, REMINDERS), country) def message_name(lines, country=None, size=56): @@ -106,16 +104,11 @@ def message_name(lines, country=None, size=56): Item('price-close-us', 'movers close US', 'movers', ('close',), at('weekdays', '16:30', NEW_YORK)), Item('rating', 'rating', 'rating', (), at(TUE_SAT)), Item('milestone', 'milestone', 'milestone', (), at(TUE_SAT)), - *(Item(f"podcasts-{name.lower().replace(' ', '-')}", f'podcasts {name}', 'podcasts', (feed,), - when.Schedule.from_json({'days': 'weekdays', 'every': 60, 'from': '10:01', 'to': '21:01', 'zone': SYDNEY})) - for name, feed in (('Money Cafe', MONEY_CAFE), ('Stocktake', STOCKTAKE))), - Item('earnings', 'earnings', 'earnings', (), at(['sun'])), - Item('shorts', 'shorts', 'shorts', (), at(['sun'])), - *periodic('weekly', ['sun']), - *periodic('monthly', {'day': 2}), - *periodic('quarterly', {'day': 2, 'months': [1, 4, 7, 10]}), - *periodic('bi-annual', {'day': 2, 'months': [1, 7]}), - *periodic('annual', {'day': 2, 'months': [1]}), + Item('earnings', 'earnings', 'earnings', (), at({'day': 1})), + Item('shorts', 'shorts', 'shorts', (), at(['sat'])), + *periodic('weekly', ['sat']), + *periodic('monthly', {'day': 1}), + *periodic('quarterly', {'day': 1, 'months': [1, 4, 7, 10]}), message('message-eofy-world', '03-31', ['🥳 Happy EOFY 🇬🇧 🇭🇰 🇮🇳 🇰🇷 🇳🇿 🇯🇵 🇿🇦']), message('message-eofy-checklist', '06-23', EOFY_CHECKLIST, 'AU'), message('message-eofy-au', '06-30', ['🥳 Happy EOFY 🇦🇺 🇧🇩 🇪🇬 🇪🇹 🇰🇪 🇳🇵 🇵🇰']), diff --git a/tests/test_schedule.py b/tests/test_schedule.py index cc13ac69..078c9eaf 100644 --- a/tests/test_schedule.py +++ b/tests/test_schedule.py @@ -81,7 +81,7 @@ def test_what_jobs_add_reads(self): for text, action, args, stored in (('movers weekly', 'movers', ['7'], {'days': ['sat'], 'at': '09:00'}), ('movers close weekdays at 4:30pm New York', 'movers', ['close'], {'days': 'weekdays', 'at': '16:30', 'zone': 'America/New_York'}), - ('performance quarterly', 'performance', ['90'], {'days': {'day': 1, 'months': [1, 4, 7, 10]}, + ('performance quarterly', 'performance', ['3m'], {'days': {'day': 1, 'months': [1, 4, 7, 10]}, 'at': '09:00'}), ('performance tue-sat at 8am', 'performance', [], {'days': ['tue', 'wed', 'thu', 'fri', 'sat'], 'at': '08:00'}), @@ -189,7 +189,7 @@ def test_every_default_job_can_be(self): """Each default job is an action a chat may schedule, with arguments its parser takes, on a schedule that runs; its key is its own; its name says what it reports on, never when; performance and movers over a period cover the days between their runs.""" - self.assertEqual((len(catalog.ITEMS), len({item.key for item in catalog.ITEMS})), (31, 31)) + self.assertEqual((len(catalog.ITEMS), len({item.key for item in catalog.ITEMS})), (25, 25)) start = datetime.datetime(2026, 1, 1, tzinfo=when.UTC) for item in catalog.ITEMS: with self.subTest(item=item.key): @@ -219,17 +219,12 @@ def test_the_default_jobs_as_a_melbourne_chat_sees_them(self): 'movers close HK · weekdays at 4:30pm Hong Kong (7:30pm local)', 'movers close UK · weekdays at 5:00pm London (3:00am local, Tue–Sat)', 'movers close US · weekdays at 4:30pm New York (7:30am local, Tue–Sat)', - 'rating · Tue–Sat at 8:30am', 'milestone · Tue–Sat at 8:30am', - 'podcasts Money Cafe · hourly at :01, weekdays 10am–9pm', - 'podcasts Stocktake · hourly at :01, weekdays 10am–9pm', - 'earnings · weekly, Sundays at 8:30am', - 'shorts · weekly, Sundays at 8:30am', 'performance · weekly, Sundays at 8:30am', - 'movers · weekly, Sundays at 8:30am', 'performance · monthly, the 2nd at 8:30am', - 'movers · monthly, the 2nd at 8:30am', 'performance · quarterly, 2 Jan/Apr/Jul/Oct at 8:30am', - 'movers · quarterly, 2 Jan/Apr/Jul/Oct at 8:30am', - 'performance · bi-annual, 2 Jan and 2 Jul at 8:30am', - 'movers · bi-annual, 2 Jan and 2 Jul at 8:30am', 'performance · annual, 2 Jan at 8:30am', - 'movers · annual, 2 Jan at 8:30am', + 'rating · Tue–Sat at 9:00am', 'milestone · Tue–Sat at 9:00am', + 'earnings · monthly, the 1st at 9:00am', + 'shorts · weekly, Saturdays at 9:00am', 'performance · weekly, Saturdays at 9:00am', + 'movers · weekly, Saturdays at 9:00am', 'performance · monthly, the 1st at 9:00am', + 'movers · monthly, the 1st at 9:00am', 'performance · quarterly, 1 Jan/Apr/Jul/Oct at 9:00am', + 'movers · quarterly, 1 Jan/Apr/Jul/Oct at 9:00am', '🥳 Happy EOFY 🇬🇧 🇭🇰 🇮🇳 🇰🇷 🇳🇿 🇯🇵 🇿🇦 · annual, 31 Mar at 8:30am', '💸 Realise capital gains/losses by EOFY June 30 (AU) · annual, 23 Jun at 8:30am', '🥳 Happy EOFY 🇦🇺 🇧🇩 🇪🇬 🇪🇹 🇰🇪 🇳🇵 🇵🇰 · annual, 30 Jun at 8:30am', @@ -259,7 +254,7 @@ def matching(text): self.assertIsNone(matching('trades every 20 mins from mon 9am to sat 3pm Brisbane')) self.assertIsNone(matching('trades every 20 mins weekdays')) self.assertEqual(matching('movers close weekdays at 4:30pm New York'), 'price-close-us') - self.assertEqual(matching('movers every sunday at 8:30am'), 'price-weekly') + self.assertEqual(matching('movers every saturday at 9am'), 'price-weekly') class Messages(FinbotCase): diff --git a/tests/test_scheduler.py b/tests/test_scheduler.py index f5308ed0..7a9112ee 100644 --- a/tests/test_scheduler.py +++ b/tests/test_scheduler.py @@ -574,7 +574,7 @@ def test_add_list_and_remove(self): which stays out of the list.""" self.assertEqual(newest(self.say('.jobs add shorts daily at 10pm')), '3. * shorts · daily at 10:00pm') self.assertEqual(self.say('.jobs'), ['Jobs here', '', 'Rating', - '1. * rating · Tue–Sat at 8:30am', '', 'Movers', + '1. * rating · Tue–Sat at 9:00am', '', 'Movers', '2. * movers close US · weekdays at 4:30pm New York (7:30am local, Tue–Sat)', '', 'Shorts', '3. * shorts · daily at 10:00pm', '', 'Trades', '4. * trades · every 20 mins, weekdays UTC', '', '* not run yet', '', @@ -584,7 +584,7 @@ def test_add_list_and_remove(self): self.assertEqual(self.say('.jobs del 4'), ['Deleted 4. trades · every 20 mins, weekdays UTC']) shorts = entry('shorts daily at 10pm', zone='Australia/Melbourne') self.assertEqual(state.load(jobs.JOBS_FILE)[CHAT], {'jobs': [shorts]}) - self.assertEqual(self.say('.jobs delete 1'), ['Deleted 1. rating · Tue–Sat at 8:30am']) + self.assertEqual(self.say('.jobs delete 1'), ['Deleted 1. rating · Tue–Sat at 9:00am']) self.assertEqual(state.load(jobs.JOBS_FILE)[CHAT], {'jobs': [shorts], 'deleted': ['rating']}) self.assertEqual([job.name for job in self.s.chat_jobs(CHAT)], ['movers close US', 'shorts']) self.assertEqual(self.say('.job remove 2'), ['Deleted 2. shorts · daily at 10:00pm']) @@ -625,7 +625,7 @@ def test_add_reads_english_and_the_period_follows_how_often(self): """A job is a report, what it takes, and a schedule in English, by the timezone setting's clock unless it names a zone; performance and movers cover the days between runs where they name no period.""" for text, line, args in (('movers weekly', 'movers · weekly, Saturdays at 9:00am', ['7']), - ('performance first day of each month at 9am', 'performance · monthly, the 1st at 9:00am', ['30']), + ('performance first day of each month at 9am', 'performance · monthly, the 1st at 9:00am', ['1m']), ('movers daily at 5pm', 'movers · daily at 5:00pm', ['interday']), ('movers 30 weekly', 'movers 30 · weekly, Saturdays at 9:00am', ['30']), ('movers midsession weekdays at 12:45pm New York', @@ -701,13 +701,13 @@ def test_a_job_the_defaults_have_switches_that_one_on(self): """A job typed as a default one is (in a zone that keeps its clock: Melbourne for Sydney) switches that one on, and brings it back where it was removed; nothing more is stored.""" self.say('.jobs toggle 1') - added = self.say('.jobs add rating tue-sat at 8:30am') - self.assertEqual(newest(added), '1. * rating · Tue–Sat at 8:30am') + added = self.say('.jobs add rating tue-sat at 9am') + self.assertEqual(newest(added), '1. * rating · Tue–Sat at 9:00am') self.assertEqual(state.load(jobs.JOBS_FILE)[CHAT], {'jobs': [entry('trades every 20 mins weekdays')]}) self.say('.jobs remove 1') self.assertEqual([job.name for job in self.s.chat_jobs(CHAT)], ['movers close US', 'trades']) - added = self.say('.jobs add rating tue-sat at 8:30am') - self.assertEqual(newest(added), '1. * rating · Tue–Sat at 8:30am') + added = self.say('.jobs add rating tue-sat at 9am') + self.assertEqual(newest(added), '1. * rating · Tue–Sat at 9:00am') self.assertEqual(state.load(jobs.JOBS_FILE)[CHAT], {'jobs': [entry('trades every 20 mins weekdays')]}) def test_run_a_job_now(self): @@ -755,7 +755,7 @@ def test_toggle_a_job_off_and_on(self): self.assertEqual(self.s.due(self.clock.now), []) self.assertEqual(self.say('.jobs toggle 3'), ['3. * trades · every 20 mins, weekdays UTC']) self.clock.now = at(13, 21, 40) - self.assertEqual([job.name for job, _ in self.s.due(self.clock.now)], ['rating', 'trades']) + self.assertEqual([job.name for job, _ in self.s.due(self.clock.now)], ['trades']) def test_a_job_is_marked_till_it_first_runs(self): """* marks a job that has never run, on its schedule or by hand; the list says what it means while it shows @@ -763,11 +763,11 @@ def test_a_job_is_marked_till_it_first_runs(self): self.say('.jobs run 3') lines = self.say('.jobs') self.assertIn('3. trades · every 20 mins, weekdays UTC', lines) - self.assertIn('1. * rating · Tue–Sat at 8:30am', lines) - self.clock.now = at(13, 21, 31) # Wednesday 8:31am in Sydney: rating has run, New York's close not yet + self.assertIn('1. * rating · Tue–Sat at 9:00am', lines) + self.clock.now = at(13, 22, 1) # Wednesday 9:01am in Sydney: rating has run, New York's close not yet self.s.tick() lines = self.say('.jobs') - self.assertIn('1. rating · Tue–Sat at 8:30am', lines) + self.assertIn('1. rating · Tue–Sat at 9:00am', lines) self.assertIn('2. * movers close US · weekdays at 4:30pm New York (7:30am local, Tue–Sat)', lines) self.assertIn('* not run yet', lines) self.say('.jobs run 2') @@ -790,7 +790,7 @@ def test_upcoming_and_system(self): self.assertEqual(self.say('.jobs next'), lines) self.assertEqual(lines[:4], ['Upcoming runs:', 'Wed 14 Oct 8:20am (21:20 UTC) – 10:40am, every 20 mins · 3. trades', - 'Wed 14 Oct 8:30am · 1. rating', + 'Wed 14 Oct 9:00am · 1. rating', 'Wed 14 Oct 11:00am (00:00 UTC) – Thu 15 Oct 10:40am, every 20 mins · 3. trades']) self.assertEqual(self.say('.jobs system'), ['System jobs:']) From b80e24b20b0cb27b3738c12976a9fe811d881186 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 29 Oct 2026 22:20:15 +0000 Subject: [PATCH 3/4] Log warnings and errors to stderr, info and debug to stdout, so Docker's journald driver files them as err and info The unit sends stdout to the journal too (the priority prefix still sets each line's priority there). Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_01JVEkZofdPjQ4jtXFKipeUX --- CLAUDE.md | 6 ++++-- bot.py | 3 ++- doc/docker.md | 3 +++ finbot.service | 2 +- lib/log.py | 16 ++++++++++++---- tests/common.py | 5 ++++- tests/test_edges.py | 36 ++++++++++++++++++++++++------------ tests/test_finbot.py | 2 +- 8 files changed, 51 insertions(+), 22 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 00f65c17..d7f9deca 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -240,8 +240,10 @@ An open PR takes in every commit pushed to its branch, so a PR opened for one sm when it uploads a chart's image: Telegram's `with_photo`), and a success answered to a network). The `log_level` setting sets what reaches the log; `lib/config.py` prints its own errors (it loads before - settings exist). Everything goes to stderr: systemd discards stdout (`StandardOutput=null`), so the bot and its reports - never print there (a test checks); only the util/ tools, run by hand, do. + settings exist). Errors and warnings go to stderr, info and debug to stdout (`log.stream`; Docker's journald driver files them as err and + info), each line starting with its syslog priority under systemd (`<3>`..`<7>`, `log.prefix`); the bot and its reports + never `print` otherwise (a test checks), only the util/ tools, run by hand, do. The tests send every level to stderr + (`log.SPLIT`). - A report gives its chart as a `render.Chart` spec, not a drawing: `deliver()` draws it only for a chat that takes charts, through `render.draw()`, which caches the image by the spec's hash (and the drawing code's), kept until cleanup: a spec's image never goes stale. Every chart's subtitle ends with the date it shows, or the dates it spans diff --git a/bot.py b/bot.py index 269fd4d8..c4e277a0 100755 --- a/bot.py +++ b/bot.py @@ -277,7 +277,8 @@ def http_server(): return waitress.create_server(main, host=config.env.ip, port=config.env.port) if __name__ == '__main__': - sys.stderr = WholeLines(sys.stderr) # threads log at once: each line goes out whole + # threads log at once: each line goes out whole + sys.stdout, sys.stderr = WholeLines(sys.stdout), WholeLines(sys.stderr) log.info(f'Starting finbot {config.git_version()}') try: config.check_startup_environment() diff --git a/doc/docker.md b/doc/docker.md index 5efc7479..fa7de42a 100644 --- a/doc/docker.md +++ b/doc/docker.md @@ -71,6 +71,9 @@ it there too: journalctl CONTAINER_NAME=finbot -f ``` +finbot logs its warnings and errors to stderr and the rest to stdout, which journald files as priority `err` (red) and +`info`, so `journalctl CONTAINER_NAME=finbot -p warning` shows the problems alone. + Elsewhere, Docker keeps the log itself (its `local` driver, which rotates it), and `docker compose logs` is the way to read it. That log is lost when the container is rebuilt. diff --git a/finbot.service b/finbot.service index ab9a991b..1a1723ba 100644 --- a/finbot.service +++ b/finbot.service @@ -15,7 +15,7 @@ ExecReload=/bin/kill -HUP $MAINPID ExecStartPre=+/opt/finbot/util/check_config.py /etc/finbot.env Restart=on-failure RestartSec=30s -StandardOutput=null +StandardOutput=journal StandardError=journal SyslogIdentifier=finbot Environment=PYTHONUNBUFFERED=1 diff --git a/lib/log.py b/lib/log.py index 246034d2..3847ec5e 100644 --- a/lib/log.py +++ b/lib/log.py @@ -1,6 +1,8 @@ -"""The log, syslog style: each line has a level, ERROR, WARN, INFO or DEBUG, and goes to stderr (which systemd and -Docker take to the journal) when the log_level setting lets it in: that level and those above it, so ERROR always -does. Each takes print()'s arguments. Under journald (JOURNAL_STREAM is set) a line starts with its syslog priority, +"""The log, syslog style: each line has a level, ERROR, WARN, INFO or DEBUG, and goes to the journal (through the +streams systemd and Docker take) when the log_level setting lets it in: that level and those above it, so ERROR always +does. Warnings and errors go to stderr, info and debug to stdout, so that Docker's journald driver files them as +err and info, and `journalctl -p warning` shows the first. Each takes print()'s arguments. +Under journald (JOURNAL_STREAM is set) a line starts with its syslog priority, <3> to <7>, which journald takes off and files the line under, so journalctl colours and filters (-p) by it; anywhere else a line has no prefix. A line that can run long (a request's URL, a chat message) goes through cut(), which puts it on one line within the log_width setting.""" @@ -10,6 +12,7 @@ from lib import config LEVELS = config.LOG_LEVELS # ERROR WARN INFO DEBUG, the most severe first +SPLIT = True # the tests send every level to stderr, as their captures read it; a test of its own turns it back on PRIORITIES = {'ERROR': 3, 'WARN': 4, 'INFO': 6, 'DEBUG': 7} # syslog's err, warning, info and debug @@ -23,11 +26,16 @@ def prefix(level): return f'<{PRIORITIES[level]}>' if os.environ.get('JOURNAL_STREAM') else '' +def stream(level): + """Where a line of this level goes: stderr for ERROR and WARN, stdout for INFO and DEBUG, SPLIT aside.""" + return sys.stdout if SPLIT and level in ('INFO', 'DEBUG') else sys.stderr + + def write(level, parts, options): """A line of these parts (and print()'s options) at this level, if log_level lets it in.""" if enabled(level): sep = str(options.pop('sep', None) or ' ') - print(prefix(level) + sep.join(str(part) for part in parts), file=sys.stderr, **options) + print(prefix(level) + sep.join(str(part) for part in parts), file=stream(level), **options) def cut(text): diff --git a/tests/common.py b/tests/common.py index dc4d01ce..b7ade0aa 100644 --- a/tests/common.py +++ b/tests/common.py @@ -14,7 +14,7 @@ import bot from lib import answer, buttons, cache, charts, config, delivery, dialects, formats, inbound, jobs, links, markets, net -from lib import render, sharesight, shortman, state, transports, watchlist, when, worker, yahoo +from lib import log, render, sharesight, shortman, state, transports, watchlist, when, worker, yahoo from lib import discord_common, slack_common, telegram_common # each network's reader and bot from lib.reports import about, earnings, history, holdings, milestone, movers, performance, profile, rankings, rating from lib.reports import shorts, trades @@ -92,6 +92,9 @@ def market_entry(ticker): 'currency': 'USD'} +log.SPLIT = False # every level goes to stderr, where the tests read the log; test_edges.LogStreams splits it + + class FinbotCase(unittest.TestCase): """Base class: self.sent collects ('photo'|'text', ...) tuples for everything the bot tried to send.""" diff --git a/tests/test_edges.py b/tests/test_edges.py index 4f4c657c..56f0cb9b 100644 --- a/tests/test_edges.py +++ b/tests/test_edges.py @@ -424,6 +424,18 @@ def each(): with self.subTest(log_level=level): self.assertEqual(self.logged(level, each), list(shown)) + def test_errors_and_warnings_go_to_stderr_and_info_and_debug_to_stdout(self): + """Docker's journald driver files stderr as err and stdout as info: warnings and errors are the first, + info and debug the second.""" + self.settings(log_level='DEBUG') + with mock.patch.object(log, 'SPLIT', True), contextlib.redirect_stderr(io.StringIO()) as err, \ + contextlib.redirect_stdout(io.StringIO()) as out: + log.error('e') + log.warn('w') + log.info('i') + log.debug('d') + self.assertEqual((err.getvalue().splitlines(), out.getvalue().splitlines()), (['e', 'w'], ['i', 'd'])) + def test_under_journald_each_line_starts_with_its_syslog_priority(self): """With JOURNAL_STREAM set, a line starts with <3> (error), <4> (warning), <6> (info) or <7> (debug), which journald takes off and files the line under; a line's print() separator is kept.""" @@ -433,7 +445,7 @@ def each(): log.warn('w', 'x', sep='-') log.info('i') log.debug('d') - with unittest.mock.patch.dict(os.environ, {'JOURNAL_STREAM': '8:1234'}): + with mock.patch.dict(os.environ, {'JOURNAL_STREAM': '8:1234'}): self.assertEqual(self.logged('DEBUG', each), ['<3>e x', '<4>w-x', '<6>i', '<7>d']) def test_a_cache_miss_hit_or_write_is_debug(self): @@ -537,7 +549,7 @@ def test_a_hosts_connections_idle_too_long_are_dropped_before_the_next_request(s clock, cleared = [1000.0], [] adapter = type('Adapter', (), {'poolmanager': type('Pools', (), {'clear': lambda self: cleared.append(1)})()})() with mock.patch.object(net.time, 'monotonic', lambda: clock[0]), mock.patch.object(net.session, 'get_adapter', - lambda url: adapter), unittest.mock.patch.dict(net._used, clear=True): + lambda url: adapter), mock.patch.dict(net._used, clear=True): net.fresh('https://api.telegram.org/bot1/sendPhoto') # the first use of a host clock[0] += net.IDLE_SECONDS - 1 net.fresh('https://api.telegram.org/bot1/sendMessage') # used a moment ago @@ -646,11 +658,11 @@ def test_finbot_starts_without_them(self): """With no webhook set, bot.py starts with the optional libraries blocked: no HTTP server, so no waitress.""" with tempfile.TemporaryDirectory() as data: proc = subprocess.Popen([sys.executable, '-u', 'bot.py'], cwd=ROOT, env=self.blocked(data), - stderr=subprocess.PIPE, stdout=subprocess.DEVNULL, text=True) + stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True) self.addCleanup(proc.wait) self.addCleanup(proc.kill) lines = [] - for line in proc.stderr: + for line in proc.stdout: lines.append(line) if line.startswith('finbot is running'): break @@ -667,8 +679,8 @@ def test_sighup_during_startup_is_ignored_and_works_afterwards(self): no_jobs(data) env = bare_environment() env.update(DATA_DIR=data, port='0') - proc = subprocess.Popen([sys.executable, '-u', 'bot.py'], cwd=ROOT, env=env, stderr=subprocess.PIPE, - stdout=subprocess.DEVNULL, text=True) + proc = subprocess.Popen([sys.executable, '-u', 'bot.py'], cwd=ROOT, env=env, stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, text=True) self.addCleanup(proc.wait) self.addCleanup(proc.kill) deadline = time.monotonic() + 30 @@ -678,13 +690,13 @@ def test_sighup_during_startup_is_ignored_and_works_afterwards(self): time.sleep(0.001) proc.send_signal(signal.SIGHUP) # still importing: the default action would kill it lines = [] - for line in proc.stderr: + for line in proc.stdout: lines.append(line) if line.startswith('finbot is running'): # the handlers are in break self.assertIsNone(proc.poll(), ''.join(lines)) proc.send_signal(signal.SIGHUP) - for line in proc.stderr: # a reload now runs (there is no settings.conf here, so it says so) + for line in proc.stdout: # a reload now runs (there is no settings.conf here, so it says so) lines.append(line) if 'reload requested' in line: break @@ -705,8 +717,8 @@ def test_usr1_flushes_the_cache_and_keeps_the_state(self): no_jobs(data) env = bare_environment() env.update(DATA_DIR=data, port='0') - proc = subprocess.Popen([sys.executable, '-u', 'bot.py'], cwd=ROOT, env=env, stderr=subprocess.PIPE, - stdout=subprocess.DEVNULL, text=True) + proc = subprocess.Popen([sys.executable, '-u', 'bot.py'], cwd=ROOT, env=env, stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, text=True) self.addCleanup(proc.wait) self.addCleanup(proc.kill) deadline = time.monotonic() + 30 @@ -716,14 +728,14 @@ def test_usr1_flushes_the_cache_and_keeps_the_state(self): time.sleep(0.001) proc.send_signal(signal.SIGUSR1) # still starting: ignored, where its default action would kill the bot lines = [] - for line in proc.stderr: + for line in proc.stdout: lines.append(line) if line.startswith('finbot is running'): # the handlers are in break self.assertIsNone(proc.poll(), ''.join(lines)) self.assertEqual(len(os.listdir(cache)), 4) # nothing flushed yet proc.send_signal(signal.SIGUSR1) - for line in proc.stderr: + for line in proc.stdout: lines.append(line) if 'cache: warm jobs done' in line: # each in a child process, as the scheduler is off break diff --git a/tests/test_finbot.py b/tests/test_finbot.py index 58129529..9c3e1920 100644 --- a/tests/test_finbot.py +++ b/tests/test_finbot.py @@ -119,7 +119,7 @@ def test_nothing_imports_pandas_numpy_or_matplotlib(self): self.assertEqual(found, []) def test_the_bot_and_its_reports_print_only_to_stderr(self): - """systemd discards stdout (StandardOutput=null), so only util/ tools, run by hand, may print there.""" + """The bot and its reports log through lib/log.py (stdout or stderr by level); only util/ tools print.""" offenders = [] for path in sorted([*Path(ROOT, 'lib').rglob('*.py'), *Path(ROOT).glob('*.py')]): for node in ast.walk(ast.parse(path.read_text())): From ff20bd7cc3d653e6649a13c4b25c215dba3044c4 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 29 Oct 2026 22:49:10 +0000 Subject: [PATCH 4/4] Tests: clear JOURNAL_STREAM, which a systemd-run CI runner sets, so log lines carry no prefix Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_01JVEkZofdPjQ4jtXFKipeUX --- tests/common.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/common.py b/tests/common.py index b7ade0aa..bfde0651 100644 --- a/tests/common.py +++ b/tests/common.py @@ -92,6 +92,7 @@ def market_entry(ticker): 'currency': 'USD'} +os.environ.pop('JOURNAL_STREAM', None) # set where the runner is a systemd service: log lines would start log.SPLIT = False # every level goes to stderr, where the tests read the log; test_edges.LogStreams splits it