Log priorities for journald and Docker, and new default jobs

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

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

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 |
 

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.
 

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

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

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 🇦🇺 🇧🇩 🇪🇬 🇪🇹 🇰🇪 🇳🇵 🇵🇰']),

lib/log.py

@@ -1,23 +1,41 @@
-"""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(),
+"""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."""
+import os
 import sys
 
 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
 
 
 def enabled(level):
 	"""Whether log_level lets lines of this level into the log."""
 	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 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):
-		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=stream(level), **options)
 
 
 def cut(text):

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,10 @@ def market_entry(ticker):
 			'currency': 'USD'}
 
 
+os.environ.pop('JOURNAL_STREAM', None) # set where the runner is a systemd service: log lines would start <N>
+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."""