diff --git a/.env.example b/.env.example index a82bfa1..4786961 100644 --- a/.env.example +++ b/.env.example @@ -102,6 +102,38 @@ HIDE_INACTIVE_ZERO_LENGTH_FROM_TOP=true # that deploying mid-day means two shrinks in quick succession: one now, one at midnight for the # next date. Deploy just after midnight if you'd rather they stay a full day apart. #DAILY_SHRINK_RUN_ON_STARTUP=true +# How many chats one shrinking statement takes on. It bounds both the rows the statement locks and +# the ones a failed batch costs, so a /grow sent at midnight waits behind one batch rather than +# behind every stale dick in the database. +#DAILY_SHRINK_BATCH_SIZE=100 + +# The run doesn't send anything: it writes one row per chat into Scheduled_Shrink_Broadcasts, in the +# same statement that shrinks the dicks, and the worker below sends them (issue #154). So a restart +# between the shrink and the summary costs nothing, and a broadcast to a few hundred thousand chats +# can take the hours it needs without holding the next midnight up. +#DAILY_SHRINK_BROADCAST_POLL_SECONDS=5 +# How many summaries one run claims, and how many of them it sends at once. The concurrency is the +# knob for throughput — a run gets through that many messages per round trip to Telegram — while the +# batch size only bounds how much it claims. Keep the concurrency under DATABASE_MAX_CONNECTIONS +# (every finished summary writes a row) and watch telegram_request_errors_total{kind="rate_limited"} +# after raising it. +#DAILY_SHRINK_BROADCAST_BATCH_SIZE=200 +#DAILY_SHRINK_BROADCAST_CONCURRENCY=16 +# How long a claimed batch stays out of every other worker's reach. A worker killed mid-batch leaves +# its summaries to be claimed again once this runs out, rather than for ever. +#DAILY_SHRINK_BROADCAST_LEASE_SECONDS=300 +# The first wait after a failure worth retrying; it doubles with each one, up to the cap. +#DAILY_SHRINK_BROADCAST_RETRY_DELAY_SECONDS=60 +#DAILY_SHRINK_BROADCAST_MAX_RETRY_DELAY_SECONDS=3600 +# Attempts before the row is marked `failed` and left alone. +#DAILY_SHRINK_BROADCAST_MAX_ATTEMPTS=3 +# How old a summary may get before it stops being worth sending. Yesterday's list of shrinks is +# still news in a chat that reads once a day; last week's is noise. Only a queue that fell behind +# can bring one there. +#DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS=48 +# How many days a finished row is kept before it is cleaned away. 0 keeps them for ever, which is +# what to set while debugging the worker — and unbounded growth on a busy bot. +#DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS=3 # Perks HELP_PUSSIES_COEF=0.01 @@ -201,11 +233,11 @@ DOD_RICH_EXCLUSION_RATIO=0.1 #MSG_SELFDESTRUCT_RETRY_DELAY_SECONDS=60 #MSG_SELFDESTRUCT_MAX_RETRY_DELAY_SECONDS=3600 #MSG_SELFDESTRUCT_MAX_ATTEMPTS=3 -# Every row that is done with is kept this many minutes before a separate cleaning process deletes +# Every row that is done with is kept this many days before a separate cleaning process deletes # it — `removed` (the message is gone), `expired` (it outlived Telegram's 48-hour limit while it # waited) or `failed` (every attempt was refused). 0 keeps them for ever, which is useful while # debugging the worker itself but grows the table without bound on a busy bot. -#MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES=1440 +#MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS=1 # Announcements are displayed at the end of the Dick of the Day message, not more than a specified # amount of times. They (max_shows + per-language texts) are configured in a YAML file — edit diff --git a/.sqlx/query-0e43b34d1b6419cae1d9df4db15c076bca67fee99b0bdcfc01570277ad1b9a25.json b/.sqlx/query-0e43b34d1b6419cae1d9df4db15c076bca67fee99b0bdcfc01570277ad1b9a25.json new file mode 100644 index 0000000..1231743 --- /dev/null +++ b/.sqlx/query-0e43b34d1b6419cae1d9df4db15c076bca67fee99b0bdcfc01570277ad1b9a25.json @@ -0,0 +1,21 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT (max(created_at)::timestamp AT TIME ZONE 'UTC') AS \"at?\" FROM Stale_Dick_Shrinks", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "at?", + "type_info": "Timestamptz", + "origin": "Expression" + } + ], + "parameters": { + "Left": [] + }, + "nullable": [ + null + ] + }, + "hash": "0e43b34d1b6419cae1d9df4db15c076bca67fee99b0bdcfc01570277ad1b9a25" +} diff --git a/.sqlx/query-11d39aa11337ffe6a385e41f4db05c28cfc8e40e35b6339d1d9b9ccdf5585468.json b/.sqlx/query-11d39aa11337ffe6a385e41f4db05c28cfc8e40e35b6339d1d9b9ccdf5585468.json new file mode 100644 index 0000000..6917372 --- /dev/null +++ b/.sqlx/query-11d39aa11337ffe6a385e41f4db05c28cfc8e40e35b6339d1d9b9ccdf5585468.json @@ -0,0 +1,14 @@ +{ + "db_name": "PostgreSQL", + "query": "DELETE FROM Scheduled_Shrink_Broadcasts WHERE finished_at IS NOT NULL AND finished_at < $1", + "describe": { + "columns": [], + "parameters": { + "Left": [ + "Timestamptz" + ] + }, + "nullable": [] + }, + "hash": "11d39aa11337ffe6a385e41f4db05c28cfc8e40e35b6339d1d9b9ccdf5585468" +} diff --git a/.sqlx/query-1fd616bda035d8b4d752b6e105076e582d93c336942840f3d41a64c50938e60a.json b/.sqlx/query-1fd616bda035d8b4d752b6e105076e582d93c336942840f3d41a64c50938e60a.json new file mode 100644 index 0000000..2d71019 --- /dev/null +++ b/.sqlx/query-1fd616bda035d8b4d752b6e105076e582d93c336942840f3d41a64c50938e60a.json @@ -0,0 +1,12 @@ +{ + "db_name": "PostgreSQL", + "query": "INSERT INTO Scheduled_Message_Deletions (message_kind, message_group, lang_code, fire_after)\n VALUES ('reply', 'notice', 'en', current_timestamp - interval '1 minute')", + "describe": { + "columns": [], + "parameters": { + "Left": [] + }, + "nullable": [] + }, + "hash": "1fd616bda035d8b4d752b6e105076e582d93c336942840f3d41a64c50938e60a" +} diff --git a/.sqlx/query-33c5bc97a1111bb38d68d7445d97e3ebdfe0f2462b281ac16125261ccc564ec8.json b/.sqlx/query-33c5bc97a1111bb38d68d7445d97e3ebdfe0f2462b281ac16125261ccc564ec8.json new file mode 100644 index 0000000..118c721 --- /dev/null +++ b/.sqlx/query-33c5bc97a1111bb38d68d7445d97e3ebdfe0f2462b281ac16125261ccc564ec8.json @@ -0,0 +1,29 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT id AS \"id: InternalChatId\" FROM Chats\n WHERE id > $1 ORDER BY id LIMIT $2", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "id: InternalChatId", + "type_info": "Int8", + "origin": { + "Table": { + "table": "chats", + "name": "id" + } + } + } + ], + "parameters": { + "Left": [ + "Int8", + "Int8" + ] + }, + "nullable": [ + false + ] + }, + "hash": "33c5bc97a1111bb38d68d7445d97e3ebdfe0f2462b281ac16125261ccc564ec8" +} diff --git a/.sqlx/query-39ed1db26f8f8bceafc8c7ee06ce09969aa7e85212bb3947156e0bdf7a47d02a.json b/.sqlx/query-39ed1db26f8f8bceafc8c7ee06ce09969aa7e85212bb3947156e0bdf7a47d02a.json new file mode 100644 index 0000000..b6fd19f --- /dev/null +++ b/.sqlx/query-39ed1db26f8f8bceafc8c7ee06ce09969aa7e85212bb3947156e0bdf7a47d02a.json @@ -0,0 +1,29 @@ +{ + "db_name": "PostgreSQL", + "query": "UPDATE Scheduled_Shrink_Broadcasts SET attempts = attempts + 1, fire_after = $2\n WHERE id = $1 RETURNING attempts AS \"attempts!: AttemptsCount\"", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "attempts!: AttemptsCount", + "type_info": "Int4", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "attempts" + } + } + } + ], + "parameters": { + "Left": [ + "Int8", + "Timestamptz" + ] + }, + "nullable": [ + false + ] + }, + "hash": "39ed1db26f8f8bceafc8c7ee06ce09969aa7e85212bb3947156e0bdf7a47d02a" +} diff --git a/.sqlx/query-48be2d4839f30fa9d94ae5f3a1fee1d7349bc88cde673240c91364368e9d66a8.json b/.sqlx/query-48be2d4839f30fa9d94ae5f3a1fee1d7349bc88cde673240c91364368e9d66a8.json new file mode 100644 index 0000000..974ba47 --- /dev/null +++ b/.sqlx/query-48be2d4839f30fa9d94ae5f3a1fee1d7349bc88cde673240c91364368e9d66a8.json @@ -0,0 +1,14 @@ +{ + "db_name": "PostgreSQL", + "query": "UPDATE Chats SET is_unreachable = false WHERE chat_id = $1 AND is_unreachable", + "describe": { + "columns": [], + "parameters": { + "Left": [ + "Int8" + ] + }, + "nullable": [] + }, + "hash": "48be2d4839f30fa9d94ae5f3a1fee1d7349bc88cde673240c91364368e9d66a8" +} diff --git a/.sqlx/query-53bf38942275781fc865a5837633169440736876386c54b221ce43c7765ecabc.json b/.sqlx/query-53bf38942275781fc865a5837633169440736876386c54b221ce43c7765ecabc.json new file mode 100644 index 0000000..3dfc3ae --- /dev/null +++ b/.sqlx/query-53bf38942275781fc865a5837633169440736876386c54b221ce43c7765ecabc.json @@ -0,0 +1,15 @@ +{ + "db_name": "PostgreSQL", + "query": "INSERT INTO Scheduled_Shrink_Broadcasts (chat_id, shrink_date, created_at) VALUES ($1, current_date - $2::int, current_timestamp - make_interval(days => $2)) ON CONFLICT DO NOTHING", + "describe": { + "columns": [], + "parameters": { + "Left": [ + "Int8", + "Int4" + ] + }, + "nullable": [] + }, + "hash": "53bf38942275781fc865a5837633169440736876386c54b221ce43c7765ecabc" +} diff --git a/.sqlx/query-63cf8355bba60bac9f076808284e409ea64192378e42b1f5070b32c4f2abd4a4.json b/.sqlx/query-63cf8355bba60bac9f076808284e409ea64192378e42b1f5070b32c4f2abd4a4.json deleted file mode 100644 index 74dbe24..0000000 --- a/.sqlx/query-63cf8355bba60bac9f076808284e409ea64192378e42b1f5070b32c4f2abd4a4.json +++ /dev/null @@ -1,85 +0,0 @@ -{ - "db_name": "PostgreSQL", - "query": "WITH victims AS (\n SELECT d.uid, d.chat_id,\n LEAST(d.length, GREATEST(1, CEIL(d.length * $1::double precision * LEAST(1.0,\n (EXTRACT(DAY FROM (current_timestamp - d.updated_at))::int - $2::bigint::int + 1)::double precision\n / GREATEST($3::bigint::int, 1)\n ))::bigint)) AS loss\n FROM Dicks d\n WHERE d.length > 0\n AND d.updated_at <= current_timestamp - make_interval(days => $2::bigint::int)\n ),\n updated AS (\n UPDATE Dicks d SET length = d.length - v.loss, bonus_attempts = d.bonus_attempts + 1\n FROM victims v WHERE d.uid = v.uid AND d.chat_id = v.chat_id\n RETURNING d.uid, d.chat_id, v.loss AS loss, d.length AS new_length\n ),\n logged AS (\n INSERT INTO Stale_Dick_Shrinks (chat_id, uid, lost_length)\n SELECT chat_id, uid, loss FROM updated\n )\n SELECT u.uid AS \"uid: UserId\", usr.name AS \"owner_name: Username\",\n u.loss AS \"lost_length!: Length\", u.new_length AS \"new_length!: Length\",\n c.chat_id AS \"messageable_chat_id: TelegramChatId\", c.is_unreachable\n FROM updated u\n JOIN Users usr USING (uid)\n JOIN Chats c ON c.id = u.chat_id", - "describe": { - "columns": [ - { - "ordinal": 0, - "name": "uid: UserId", - "type_info": "Int8", - "origin": { - "Table": { - "table": "dicks", - "name": "uid" - } - } - }, - { - "ordinal": 1, - "name": "owner_name: Username", - "type_info": "Varchar", - "origin": { - "Table": { - "table": "users", - "name": "name" - } - } - }, - { - "ordinal": 2, - "name": "lost_length!: Length", - "type_info": "Int8", - "origin": "Expression" - }, - { - "ordinal": 3, - "name": "new_length!: Length", - "type_info": "Int8", - "origin": { - "Table": { - "table": "dicks", - "name": "length" - } - } - }, - { - "ordinal": 4, - "name": "messageable_chat_id: TelegramChatId", - "type_info": "Int8", - "origin": { - "Table": { - "table": "chats", - "name": "chat_id" - } - } - }, - { - "ordinal": 5, - "name": "is_unreachable", - "type_info": "Bool", - "origin": { - "Table": { - "table": "chats", - "name": "is_unreachable" - } - } - } - ], - "parameters": { - "Left": [ - "Float8", - "Int8", - "Int8" - ] - }, - "nullable": [ - false, - false, - null, - false, - true, - false - ] - }, - "hash": "63cf8355bba60bac9f076808284e409ea64192378e42b1f5070b32c4f2abd4a4" -} diff --git a/.sqlx/query-6c30147b089c4a00a9d20a2dea43ae2fce6e6f1d8331fd61554481f0088927e8.json b/.sqlx/query-6c30147b089c4a00a9d20a2dea43ae2fce6e6f1d8331fd61554481f0088927e8.json new file mode 100644 index 0000000..3e7d2c5 --- /dev/null +++ b/.sqlx/query-6c30147b089c4a00a9d20a2dea43ae2fce6e6f1d8331fd61554481f0088927e8.json @@ -0,0 +1,28 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT state::text AS \"state!\", count(*) AS \"count!\" FROM Scheduled_Shrink_Broadcasts\n WHERE finished_at IS NOT NULL GROUP BY state ORDER BY 1", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "state!", + "type_info": "Text", + "origin": "Expression" + }, + { + "ordinal": 1, + "name": "count!", + "type_info": "Int8", + "origin": "Expression" + } + ], + "parameters": { + "Left": [] + }, + "nullable": [ + null, + null + ] + }, + "hash": "6c30147b089c4a00a9d20a2dea43ae2fce6e6f1d8331fd61554481f0088927e8" +} diff --git a/.sqlx/query-71439e937c0a8d818607f39a4280fa9312ba797efa7b96e06de25107dc4dc582.json b/.sqlx/query-71439e937c0a8d818607f39a4280fa9312ba797efa7b96e06de25107dc4dc582.json new file mode 100644 index 0000000..0067e55 --- /dev/null +++ b/.sqlx/query-71439e937c0a8d818607f39a4280fa9312ba797efa7b96e06de25107dc4dc582.json @@ -0,0 +1,21 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT count(*) AS \"count!: Count\"\n FROM Scheduled_Shrink_Broadcasts WHERE finished_at IS NULL", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "count!: Count", + "type_info": "Int8", + "origin": "Expression" + } + ], + "parameters": { + "Left": [] + }, + "nullable": [ + null + ] + }, + "hash": "71439e937c0a8d818607f39a4280fa9312ba797efa7b96e06de25107dc4dc582" +} diff --git a/.sqlx/query-7872c56ca1d2ec63a1342ff17d7d96f828886335e682c39b42990428fa8777f3.json b/.sqlx/query-7872c56ca1d2ec63a1342ff17d7d96f828886335e682c39b42990428fa8777f3.json new file mode 100644 index 0000000..424fe3c --- /dev/null +++ b/.sqlx/query-7872c56ca1d2ec63a1342ff17d7d96f828886335e682c39b42990428fa8777f3.json @@ -0,0 +1,72 @@ +{ + "db_name": "PostgreSQL", + "query": "UPDATE Scheduled_Shrink_Broadcasts b SET fire_after = $2\n WHERE b.id IN (\n SELECT id FROM Scheduled_Shrink_Broadcasts\n WHERE fire_after <= current_timestamp AND finished_at IS NULL\n ORDER BY fire_after\n LIMIT $1\n FOR UPDATE SKIP LOCKED\n )\n RETURNING b.id AS \"id: ScheduledBroadcastId\",\n (SELECT c.chat_id FROM Chats c WHERE c.id = b.chat_id) AS \"chat_id: TelegramChatId\",\n b.shrink_date, b.created_at, b.attempts AS \"attempts!: AttemptsCount\"", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "id: ScheduledBroadcastId", + "type_info": "Int8", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "id" + } + } + }, + { + "ordinal": 1, + "name": "chat_id: TelegramChatId", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 2, + "name": "shrink_date", + "type_info": "Date", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "shrink_date" + } + } + }, + { + "ordinal": 3, + "name": "created_at", + "type_info": "Timestamptz", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "created_at" + } + } + }, + { + "ordinal": 4, + "name": "attempts!: AttemptsCount", + "type_info": "Int4", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "attempts" + } + } + } + ], + "parameters": { + "Left": [ + "Int8", + "Timestamptz" + ] + }, + "nullable": [ + false, + null, + false, + false, + false + ] + }, + "hash": "7872c56ca1d2ec63a1342ff17d7d96f828886335e682c39b42990428fa8777f3" +} diff --git a/.sqlx/query-7c677d6a99538183876ec8bfd96e5d9856b45dd2b9b2015628942ff5af5ce6df.json b/.sqlx/query-7c677d6a99538183876ec8bfd96e5d9856b45dd2b9b2015628942ff5af5ce6df.json new file mode 100644 index 0000000..3fac822 --- /dev/null +++ b/.sqlx/query-7c677d6a99538183876ec8bfd96e5d9856b45dd2b9b2015628942ff5af5ce6df.json @@ -0,0 +1,26 @@ +{ + "db_name": "PostgreSQL", + "query": "INSERT INTO Chats (chat_instance) VALUES ('inline-only') RETURNING id", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "id", + "type_info": "Int8", + "origin": { + "Table": { + "table": "chats", + "name": "id" + } + } + } + ], + "parameters": { + "Left": [] + }, + "nullable": [ + false + ] + }, + "hash": "7c677d6a99538183876ec8bfd96e5d9856b45dd2b9b2015628942ff5af5ce6df" +} diff --git a/.sqlx/query-a1a88349f7980280319dcc55b3a9836dd8cbdd8640333d44bb4e51a76c6c28ac.json b/.sqlx/query-a1a88349f7980280319dcc55b3a9836dd8cbdd8640333d44bb4e51a76c6c28ac.json new file mode 100644 index 0000000..a9fe79f --- /dev/null +++ b/.sqlx/query-a1a88349f7980280319dcc55b3a9836dd8cbdd8640333d44bb4e51a76c6c28ac.json @@ -0,0 +1,33 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT chat_id, state::text AS \"state!\" FROM Scheduled_Shrink_Broadcasts\n WHERE shrink_date = current_date ORDER BY chat_id", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "chat_id", + "type_info": "Int8", + "origin": { + "Table": { + "table": "scheduled_shrink_broadcasts", + "name": "chat_id" + } + } + }, + { + "ordinal": 1, + "name": "state!", + "type_info": "Text", + "origin": "Expression" + } + ], + "parameters": { + "Left": [] + }, + "nullable": [ + false, + null + ] + }, + "hash": "a1a88349f7980280319dcc55b3a9836dd8cbdd8640333d44bb4e51a76c6c28ac" +} diff --git a/.sqlx/query-eab1e2bcee8fc455f395a2d558bbd80f3537bc6fae40fcc001b5d35e184d8ef1.json b/.sqlx/query-eab1e2bcee8fc455f395a2d558bbd80f3537bc6fae40fcc001b5d35e184d8ef1.json new file mode 100644 index 0000000..fa62b99 --- /dev/null +++ b/.sqlx/query-eab1e2bcee8fc455f395a2d558bbd80f3537bc6fae40fcc001b5d35e184d8ef1.json @@ -0,0 +1,28 @@ +{ + "db_name": "PostgreSQL", + "query": "UPDATE Scheduled_Shrink_Broadcasts SET state = $2, finished_at = current_timestamp WHERE id = $1", + "describe": { + "columns": [], + "parameters": { + "Left": [ + "Int8", + { + "Custom": { + "name": "broadcast_state", + "kind": { + "Enum": [ + "created", + "sent", + "unreachable", + "expired", + "failed" + ] + } + } + } + ] + }, + "nullable": [] + }, + "hash": "eab1e2bcee8fc455f395a2d558bbd80f3537bc6fae40fcc001b5d35e184d8ef1" +} diff --git a/.sqlx/query-f1eeee66f9502a559fc1741a89c7b58127cd7814e3eaf8bfff7d96f85bddd489.json b/.sqlx/query-f1eeee66f9502a559fc1741a89c7b58127cd7814e3eaf8bfff7d96f85bddd489.json new file mode 100644 index 0000000..a2ed539 --- /dev/null +++ b/.sqlx/query-f1eeee66f9502a559fc1741a89c7b58127cd7814e3eaf8bfff7d96f85bddd489.json @@ -0,0 +1,61 @@ +{ + "db_name": "PostgreSQL", + "query": "WITH victims AS (\n SELECT d.uid, d.chat_id,\n LEAST(d.length, GREATEST(1, CEIL(d.length * $1::double precision * LEAST(1.0,\n (EXTRACT(DAY FROM (current_timestamp - d.updated_at))::int - $2::bigint::int + 1)::double precision\n / GREATEST($3::bigint::int, 1)\n ))::bigint)) AS loss\n FROM Dicks d\n WHERE d.chat_id = ANY($4)\n AND d.length > 0\n AND d.updated_at <= current_timestamp - make_interval(days => $2::bigint::int)\n ),\n updated AS (\n UPDATE Dicks d SET length = d.length - v.loss, bonus_attempts = d.bonus_attempts + 1\n FROM victims v WHERE d.uid = v.uid AND d.chat_id = v.chat_id\n RETURNING d.uid, d.chat_id, v.loss AS loss\n ),\n logged AS (\n INSERT INTO Stale_Dick_Shrinks (chat_id, uid, lost_length)\n SELECT chat_id, uid, loss FROM updated\n ),\n classified AS (\n SELECT u.uid, u.chat_id, c.chat_id IS NOT NULL AS messageable, c.is_unreachable\n FROM updated u JOIN Chats c ON c.id = u.chat_id\n ),\n queued AS (\n INSERT INTO Scheduled_Shrink_Broadcasts (chat_id, shrink_date)\n SELECT DISTINCT chat_id, current_date FROM classified\n WHERE messageable AND NOT is_unreachable\n ON CONFLICT DO NOTHING\n RETURNING chat_id\n )\n SELECT count(*) AS \"victims!: Count\",\n count(*) FILTER (WHERE messageable AND NOT is_unreachable) AS \"to_broadcast!: Count\",\n count(*) FILTER (WHERE NOT messageable) AS \"inline_only!: Count\",\n count(*) FILTER (WHERE messageable AND is_unreachable) AS \"unreachable!: Count\",\n (SELECT count(*) FROM queued) AS \"chats_queued!: Count\",\n count(DISTINCT chat_id) FILTER (WHERE messageable AND is_unreachable) AS \"chats_skipped!: Count\"\n FROM classified", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "victims!: Count", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 1, + "name": "to_broadcast!: Count", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 2, + "name": "inline_only!: Count", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 3, + "name": "unreachable!: Count", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 4, + "name": "chats_queued!: Count", + "type_info": "Int8", + "origin": "Expression" + }, + { + "ordinal": 5, + "name": "chats_skipped!: Count", + "type_info": "Int8", + "origin": "Expression" + } + ], + "parameters": { + "Left": [ + "Float8", + "Int8", + "Int8", + "Int8Array" + ] + }, + "nullable": [ + null, + null, + null, + null, + null, + null + ] + }, + "hash": "f1eeee66f9502a559fc1741a89c7b58127cd7814e3eaf8bfff7d96f85bddd489" +} diff --git a/.sqlx/query-f553c3867e0f2588eb2ad57099ecf079eccafd28e0789f0fa8fcd4ae54c65a85.json b/.sqlx/query-f553c3867e0f2588eb2ad57099ecf079eccafd28e0789f0fa8fcd4ae54c65a85.json new file mode 100644 index 0000000..4db2b00 --- /dev/null +++ b/.sqlx/query-f553c3867e0f2588eb2ad57099ecf079eccafd28e0789f0fa8fcd4ae54c65a85.json @@ -0,0 +1,28 @@ +{ + "db_name": "PostgreSQL", + "query": "SELECT lost_length FROM Stale_Dick_Shrinks WHERE uid = $1 AND created_at = current_date", + "describe": { + "columns": [ + { + "ordinal": 0, + "name": "lost_length", + "type_info": "Int8", + "origin": { + "Table": { + "table": "stale_dick_shrinks", + "name": "lost_length" + } + } + } + ], + "parameters": { + "Left": [ + "Int8" + ] + }, + "nullable": [ + false + ] + }, + "hash": "f553c3867e0f2588eb2ad57099ecf079eccafd28e0789f0fa8fcd4ae54c65a85" +} diff --git a/.sqlx/query-fa12c6a161068cc2f0360936acb7939d4f2d8c64fc8da71ccf0c0c98a0e19f42.json b/.sqlx/query-fa12c6a161068cc2f0360936acb7939d4f2d8c64fc8da71ccf0c0c98a0e19f42.json deleted file mode 100644 index 5abc63b..0000000 --- a/.sqlx/query-fa12c6a161068cc2f0360936acb7939d4f2d8c64fc8da71ccf0c0c98a0e19f42.json +++ /dev/null @@ -1,12 +0,0 @@ -{ - "db_name": "PostgreSQL", - "query": "INSERT INTO Scheduled_Message_Deletions (message_kind, message_group, lang_code, fire_after)\n VALUES ('reply', 'notice', 'en', current_timestamp - interval '1 minute')", - "describe": { - "columns": [], - "parameters": { - "Left": [] - }, - "nullable": [] - }, - "hash": "fa12c6a161068cc2f0360936acb7939d4f2d8c64fc8da71ccf0c0c98a0e19f42" -} diff --git a/CLAUDE.md b/CLAUDE.md index ca313b9..cebaf13 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -188,7 +188,7 @@ MSG_SELFDESTRUCT_INLINE_GROUPS= # comma-separated groups; empty => inlin MSG_SELFDESTRUCT_RETRY_DELAY_SECONDS=60 # the first wait after a failure; it doubles with each one MSG_SELFDESTRUCT_MAX_RETRY_DELAY_SECONDS=3600 # the cap that doubling stops at MSG_SELFDESTRUCT_MAX_ATTEMPTS=3 # attempts before the row is marked `failed` and left alone -MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES=1440 # minutes a finished row is kept; 0 => for ever +MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS=1 # days a finished row is kept; 0 => for ever ``` **Every chat may overrule all of that** with `/cleanup` (issue #128), an admins-only picker that @@ -321,7 +321,7 @@ warned into the void and found missing again a grace period later — the notice edit costs, but a message that is gone is not coming back. `SELECT state, count(*) … WHERE finished_at IS NOT NULL` is the first thing to look at when messages stop disappearing; the same numbers are exported as `self_destruction_finished{state}`. -`scheduler::spawn_deletion_cleaner` deletes them `MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES` minutes +`scheduler::spawn_deletion_cleaner` deletes them `MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS` days later — a task of its own, because clearing the history must never be part of the run that wrote it. **A retention of 0 keeps everything for ever**: right while debugging the worker, unbounded growth on a busy bot. @@ -399,13 +399,105 @@ Two limits are Telegram's: An application answered before it expires is *cancelled* (`loan.rs`, `pvp.rs`): the message has stopped being an offer, and its outcome is kept like any other event. +### The daily shrink and its broadcast queue + +The shrink and the summaries it owes are **two jobs, not one** (issue #154). `run_daily_shrink` +applies the decay and writes a row per chat; `scheduler/broadcasts.rs` sends them. Nothing is held +in memory between the two. + +That split is not tidiness. At ~204k chats and ~1.3M victims a day, the old single function held +the whole day's events in a `HashMap` and sent to each chat in turn — one `await` per chat, with a +user-service language call inside the loop — so a run took days rather than minutes. And the loop +around it sleeps only *after* the run returns, so a run that outlasts the day takes the next +midnight with it: five runs were logged in the fortnight before this was fixed, with the gaps +growing. Everything below follows from that. + +* **The enqueue is a CTE of the shrinking statement**, so there is no moment at which a shrink is + committed and its summary is not owed. `Scheduled_Shrink_Broadcasts` (migration 38) is a + transactional outbox, and that is the property a message broker could not provide: publishing + after committing is a dual write, and a crash in between loses exactly what this exists to keep. +* **The run walks the chats in batches** of `DAILY_SHRINK_BATCH_SIZE`, read from `Chats` by keyset + on the primary key (`select_chats_batch`), so it holds one batch at a time however many chats + there are. Per chat is the right granularity because that is the granularity a summary has: each + batch is shrunk by one atomic statement, the locks and the memory are bounded, and a failed batch + costs its own chats instead of the day. A `/grow` at midnight then waits behind one batch rather + than behind every stale dick in the database. + + It reads *every* chat rather than only the ones with something to shrink, on purpose: that + question needs a `DISTINCT` over about a million stale dicks, and it would exclude roughly one + chat in eight, because nearly every chat has a neglected dick in it. A batch whose chats have + nothing stale shrinks nothing and costs an index lookup. +* **Nothing comes back from the statement but counts.** The shrinks are in `Stale_Dick_Shrinks` and + `get_shrinks_for_date` already reads exactly the page a summary needs, so the worker re-reads + rather than carrying a payload. Page 0 therefore comes from the same `ORDER BY lost_length DESC` + as pages 1+, which the in-memory version did not — its "next page" button could repeat or skip + people. +* **The worker is a copy of `scheduler/deletions.rs`**: claim-with-lease, `for_each_concurrent`, + exponential back-off, `finish()` writing the row and the counter together. `UNIQUE (chat_id, + shrink_date)` makes the enqueue idempotent, so re-running a day can't double-send. The two + indexes are complements — `(fire_after) WHERE finished_at IS NULL` for the claim, + `(finished_at) WHERE finished_at IS NOT NULL` for the cleaner — each leaving out what the other + is about. +* **`DAILY_SHRINK_BROADCAST_CONCURRENCY` is the throughput knob**, not the batch size: a run gets through + that many messages per round trip. Keep it under `DATABASE_MAX_CONNECTIONS` — every finished + summary writes a row — and watch `telegram_request_errors_total{kind="rate_limited"}`. +* **A rejection teloxide has a variant for is final** (`scheduler::broadcasts::is_final`): Telegram + thought about it and refused, so the same payload gets the same answer, and three attempts across + 199k chats is an outage rather than a hiccup. `ApiError::Unknown` stays retryable — Telegram's own + 5xx answers arrive that way — unless its text says the chat is unreachable. +* **A summary older than `DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS` is `expired`** without spending a request. + Yesterday's list is still news in a chat that reads once a day; last week's is noise. + +``` +DAILY_SHRINK_RATIO=0.01 # unset or 0 => the whole feature is off, queue included +DAILY_SHRINK_INACTIVITY_DAYS=7 +DAILY_SHRINK_RAMP_UP_DAYS=7 +DAILY_SHRINK_RUN_ON_STARTUP=false # run once at startup instead of waiting for UTC midnight +DAILY_SHRINK_BATCH_SIZE=100 # chats per shrinking statement +DAILY_SHRINK_BROADCAST_POLL_SECONDS=5 +DAILY_SHRINK_BROADCAST_BATCH_SIZE=200 # summaries one run claims +DAILY_SHRINK_BROADCAST_CONCURRENCY=16 # how many it sends at once — the throughput knob +DAILY_SHRINK_BROADCAST_LEASE_SECONDS=300 +DAILY_SHRINK_BROADCAST_RETRY_DELAY_SECONDS=60 +DAILY_SHRINK_BROADCAST_MAX_RETRY_DELAY_SECONDS=3600 +DAILY_SHRINK_BROADCAST_MAX_ATTEMPTS=3 +DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS=48 # older than this and the summary is `expired` unsent +DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS=3 # 0 => finished rows are kept for ever +``` + +**Whether the scheduler is alive is `daily_shrink_last_run_timestamp_seconds`**, a gauge read from +`MAX(created_at)` in `Stale_Dick_Shrinks`, not any of the `daily_shrink_*` counters. A counter that +moves once a day reads zero both when nothing happened and when nobody scraped it before the process +restarted, and nothing afterwards tells the two apart — which is how a fortnight of silence went +unnoticed. Alert on `time() - daily_shrink_last_run_timestamp_seconds > 26h`, and on +`daily_shrink_broadcast_pending` staying above zero for hours. Both live in the server-configs +repo's `vmalert/metrics-alerts.yml`, next to the Grafana dashboard. + +**Those two are the only gauges, and only the worker's tick publishes them.** They exist because +vmalert reads Prometheus and cannot query SQL; everything a human looks at — which chats failed and +why, the states over time — is a panel over `Scheduled_Shrink_Broadcasts` through Grafana's Postgres +datasource, which costs nothing when nobody is looking. A gauge over the finished rows was the +opposite trade: grouping a few hundred thousand rows by state every five seconds so that a graph +could show what one SQL query already answers. + +**A log line's level follows what was lost, not whether the code recovered.** A failed shrink page +is an `error!`: those chats lost the day and nothing retries it. A failed metric publication is a +`warn!`: one sample of a gauge is gone, the next tick replaces it, and the database problem behind +it has already been reported by the run that hit it. + +`Chats.is_unreachable` keeps a chat out of the queue, and is cleared by `handlers::rights` on the +`my_chat_member` update that says the bot may post again — re-added, or un-muted by an +administrator. Telegram sends that update either way, so nothing polls and nobody has to type a +command in the chat first. It is only ever *taken off* there: whether the bot lost the right is what +a failed send finds out. + ### One throttle for the schedulers -The daily shrink and the deletion worker both reach many chats at once, and both hold -`teloxide`'s `Throttle`. They share **one**, built by `scheduler::throttled` and cloned into both -(`main.rs`). +The daily shrink's broadcast worker and the deletion worker both reach many chats at once, and both +hold `teloxide`'s `Throttle`. They share **one**, built by `scheduler::throttled` and cloned into +both (`main.rs`). -**It only governs the shrink.** The adaptor throttles the message-*sending* methods and passes +**It only governs the broadcast.** The adaptor throttles the message-*sending* methods and passes everything else through, so the deletion worker — which only deletes and edits — is not bounded by it at all. That is teloxide's judgement, not an oversight: the documented limits (30 a second, one a second per chat) are about sending, and a deletion produces no message and no notification. What @@ -481,6 +573,26 @@ to match them against. Records of the exporter's own stack (`opentelemetry`, `hy `reqwest`) are never exported: the exporter logs while it sends, and those records would be sent again. `observability::tests` covers the whole path against a VictoriaLogs container. +**A record also carries the fields of every span it was written inside**, from the root down, the +nearer span winning where two of them name the same field. That is what makes "a log message is a +constant; the values are fields" pay off in the log database rather than only on the console: a +message that leaves `chat_id` out of its text is still searchable by it. It takes the +`experimental_span_attributes` feature of `opentelemetry-appender-tracing` and +`build_logs_bridge`; without them the SDK exports the two ids and nothing else, and every +`#[tracing::instrument(fields(…))]` in the bot is worth something to the traces and nothing to +VictoriaLogs. Every field is taken rather than a named few — a span's fields are already chosen by +hand at each `#[tracing::instrument]`, and an allowlist would be a second list to keep in step. + +**A span decorates only what is logged while it is entered**, which is the catch for an error that +travels. A repository returns its errors instead of logging them, so by the time +`ContextLoggingErrorHandler` writes the record — in the dispatcher's task — both the repo's span +and the handler's have closed, and nothing is left to carry the ids. So the two cases part ways: + +* an error **handled where it is created** — the read-through caches, the schedulers, + `handlers::rights` — is logged inside the caller's span, and its context may be a constant; +* an error that **escapes to the dispatcher's error handler** keeps its ids in the text of its + `.context(…)`, because nothing else will carry them there. + `docker-compose.yml` bundles an **optional** observability stack — Jaeger for the spans, VictoriaLogs for the records — gated behind the `tracing` Compose profile. The `infra`/`infra:full` tasks start both (they name them, activating the profile) and `docker-compose.override.yml` @@ -508,8 +620,15 @@ Each request produces three things: * `telegram_request_duration_seconds{method,outcome}` — how long the call took. The failed calls are measured too, so a timeout (the slowest case there is) is in the histogram rather than - missing from it. `outcome` is `ok` or one of the kinds `telegram_request_errors_total` uses; both - come from the same `error_handler::classify`, so the two metrics always agree. + missing from it. `outcome` is `ok` or one of the kinds `telegram_request_errors_total` uses. +* `telegram_request_errors_total{kind}` — the failures of that same call, from that same + `error_handler::classify`. One classification feeds both, so the two can't disagree. It is + counted **here** rather than at the dispatcher's error handler, which is the only place that sees + requests at all: the schedulers never reach a dispatcher, so a broadcast-wide outage left the + counter flat. The observer sits under every adaptor, so it sees them and polling's `getUpdates` + alike. One consequence worth knowing: `Throttle` retries after a flood wait and the observer is + below it, so `rate_limited` counts every rejection where the handler only ever saw the last one. + `ContextLoggingErrorHandler` now only logs. * a `telegram_request` client span, so a slow API call is a child span of the handler's trace instead of an unattributed gap inside it. * when the API answers with `ApiError::Unknown` — its way of saying it disliked the payload without @@ -840,10 +959,16 @@ Runtime features are gated by environment variables parsed in `config/`. Check ` let debt: i64 = value.saturating_into(); ``` - **Where the sink is ours, the conversion belongs to it, not to the caller.** `Gauge::set` and - `Histogram::observe` (`src/metrics.rs`) take `impl SaturatingInto` / `impl ApproxInto`, - so a caller hands over the domain value itself. The repo layer has done this all along: a query - binds `uid as UserId` and sqlx's `Encode` does the converting. + **Where the sink is ours *and* the conversion is always the same, it belongs to the sink.** The + repo layer does this: a query binds `uid as UserId` and sqlx's `Encode` does the converting. + + The metrics are the counter-example, and worth knowing before trying to tidy them. `Gauge::set` + and `Histogram::observe` (`src/metrics.rs`) take a bare `i64` / `f64`, and the callers name the + conversion. They cannot do otherwise: `domain_types` implements these traits **only for the pairs + that lose something**, on the principle that an exact conversion must say `From`. So there is no + `SaturatingInto for i64`, and a caller holding a Unix timestamp could not satisfy such a + bound at all — while a caller holding a `Count` or a `usize` genuinely is narrowing and should + say so. A cast that is genuinely right keeps an `#[allow]` carrying the reason, on the narrowest scope that works — never a whole function, or it will also cover the next cast written on that line. diff --git a/Cargo.toml b/Cargo.toml index 274813d..541b5fe 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -44,7 +44,7 @@ tracing-opentelemetry = "0.33.0" opentelemetry = "0.32.0" opentelemetry_sdk = { version = "0.32.1", features = ["rt-tokio"] } opentelemetry-otlp = { version = "0.32.0", features = ["grpc-tonic"] } -opentelemetry-appender-tracing = "0.32.0" +opentelemetry-appender-tracing = { version = "0.32.0", features = ["experimental_span_attributes"] } tonic-tracing-opentelemetry = "0.38.0" tower = "0.5.3" dotenvy = "0.15.7" diff --git a/Dockerfile b/Dockerfile index 5f4a6a5..c28a38c 100644 --- a/Dockerfile +++ b/Dockerfile @@ -84,6 +84,16 @@ ARG DAILY_SHRINK_RATIO ARG DAILY_SHRINK_INACTIVITY_DAYS ARG DAILY_SHRINK_RAMP_UP_DAYS ARG DAILY_SHRINK_RUN_ON_STARTUP +ARG DAILY_SHRINK_BATCH_SIZE +ARG DAILY_SHRINK_BROADCAST_POLL_SECONDS +ARG DAILY_SHRINK_BROADCAST_BATCH_SIZE +ARG DAILY_SHRINK_BROADCAST_CONCURRENCY +ARG DAILY_SHRINK_BROADCAST_LEASE_SECONDS +ARG DAILY_SHRINK_BROADCAST_RETRY_DELAY_SECONDS +ARG DAILY_SHRINK_BROADCAST_MAX_RETRY_DELAY_SECONDS +ARG DAILY_SHRINK_BROADCAST_MAX_ATTEMPTS +ARG DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS +ARG DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS ARG HELP_PUSSIES_COEF ARG LOAN_PAYOUT_COEF ARG DOD_SELECTION_MODE @@ -117,7 +127,7 @@ ARG MSG_SELFDESTRUCT_INLINE_GROUPS ARG MSG_SELFDESTRUCT_RETRY_DELAY_SECONDS ARG MSG_SELFDESTRUCT_MAX_RETRY_DELAY_SECONDS ARG MSG_SELFDESTRUCT_MAX_ATTEMPTS -ARG MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES +ARG MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS ARG BOT_HTTP_CONNECT_TIMEOUT_SECONDS ARG BOT_HTTP_TIMEOUT_SECONDS ARG SUPPORT_CHAT_ID diff --git a/docker-compose.yml b/docker-compose.yml index 0edad82..fef1a28 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -38,6 +38,16 @@ services: - DAILY_SHRINK_INACTIVITY_DAYS - DAILY_SHRINK_RAMP_UP_DAYS - DAILY_SHRINK_RUN_ON_STARTUP + - DAILY_SHRINK_BATCH_SIZE + - DAILY_SHRINK_BROADCAST_POLL_SECONDS + - DAILY_SHRINK_BROADCAST_BATCH_SIZE + - DAILY_SHRINK_BROADCAST_CONCURRENCY + - DAILY_SHRINK_BROADCAST_LEASE_SECONDS + - DAILY_SHRINK_BROADCAST_RETRY_DELAY_SECONDS + - DAILY_SHRINK_BROADCAST_MAX_RETRY_DELAY_SECONDS + - DAILY_SHRINK_BROADCAST_MAX_ATTEMPTS + - DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS + - DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS - HELP_PUSSIES_COEF - LOAN_PAYOUT_COEF - DOD_SELECTION_MODE @@ -71,7 +81,7 @@ services: - MSG_SELFDESTRUCT_RETRY_DELAY_SECONDS - MSG_SELFDESTRUCT_MAX_RETRY_DELAY_SECONDS - MSG_SELFDESTRUCT_MAX_ATTEMPTS - - MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES + - MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS - BOT_HTTP_CONNECT_TIMEOUT_SECONDS - BOT_HTTP_TIMEOUT_SECONDS - SUPPORT_CHAT_ID diff --git a/migrations/38_create-scheduled-shrink-broadcasts-table.sql b/migrations/38_create-scheduled-shrink-broadcasts-table.sql new file mode 100644 index 0000000..9771040 --- /dev/null +++ b/migrations/38_create-scheduled-shrink-broadcasts-table.sql @@ -0,0 +1,39 @@ +DO $$ BEGIN + CREATE TYPE broadcast_state AS ENUM ( + 'created', + 'sent', + 'unreachable', + 'expired', + 'failed' + ); +EXCEPTION + WHEN duplicate_object THEN null; +END $$; + +CREATE TABLE IF NOT EXISTS Scheduled_Shrink_Broadcasts ( + id bigserial PRIMARY KEY, + chat_id bigint NOT NULL REFERENCES Chats(id), + shrink_date date NOT NULL, + fire_after timestamptz NOT NULL DEFAULT current_timestamp, + state broadcast_state NOT NULL DEFAULT 'created', + attempts int NOT NULL DEFAULT 0, + created_at timestamptz NOT NULL DEFAULT current_timestamp, + finished_at timestamptz +); + +-- The two partial indexes are complements: the claim only ever reads unfinished rows and the +-- cleaner only ever reads finished ones, so each index leaves out exactly what the other is about. +CREATE INDEX IF NOT EXISTS Scheduled_Shrink_Broadcasts_fire_after_idx + ON Scheduled_Shrink_Broadcasts (fire_after) WHERE finished_at IS NULL; +CREATE INDEX IF NOT EXISTS Scheduled_Shrink_Broadcasts_finished_at_idx + ON Scheduled_Shrink_Broadcasts (finished_at) WHERE finished_at IS NOT NULL; +CREATE UNIQUE INDEX IF NOT EXISTS Scheduled_Shrink_Broadcasts_chat_date_idx + ON Scheduled_Shrink_Broadcasts (chat_id, shrink_date); + +COMMENT ON TABLE Scheduled_Shrink_Broadcasts IS 'The daily shrink summaries a chat is owed, and what became of the ones that are done with; the cleaning process takes the latter away'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.chat_id IS 'The internal id of the chat, so that a group migrated to a supergroup is addressed by its new Telegram id at send time'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.shrink_date IS 'The day whose shrinks the summary is about; the text is read from Stale_Dick_Shrinks by it'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.fire_after IS 'The moment the row becomes a candidate; the worker polls, so it acts somewhat later'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.attempts IS 'Failed attempts to send the summary; the row is given up on after a few of them'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.created_at IS 'When the shrink that owes this summary was committed'; +COMMENT ON COLUMN Scheduled_Shrink_Broadcasts.finished_at IS 'When the row was sent, expired or given up on; NULL while it is still actionable'; diff --git a/migrations/39_index-uid-and-chat-id-lookups.sql b/migrations/39_index-uid-and-chat-id-lookups.sql new file mode 100644 index 0000000..8d02819 --- /dev/null +++ b/migrations/39_index-uid-and-chat-id-lookups.sql @@ -0,0 +1,26 @@ +-- Three tables were being read by a column that led no index, and so were scanned in full every +-- time: the whole of Dicks to give one user their promo bonus or their statistics, the whole of +-- Loans and of Battle_Stats to merge two chats — the latter three times over, plus a fourth for the +-- cascade from Chats. +-- +-- Where every query names both columns anyway, one index serves both shapes: equality on a pair is +-- matched whichever column comes first, which leaves the leading one free to be the chat, and the +-- separate index on the user is then redundant. That is why two of the tables come out of this with +-- one index fewer than they went in with. What it costs is the queries that filter by the user +-- alone, which is erasing a user — run by hand, on a request, and never by the bot. +-- +-- Foreign keys are unaffected: an insert checks the key against the parent's own primary key, so it +-- never looks at these indexes. Only deleting a row from Users would, and the bot deletes none. +CREATE INDEX IF NOT EXISTS dicks_idx_uid ON Dicks(uid); + +CREATE INDEX IF NOT EXISTS idx_loans_chat_id_uid ON Loans(chat_id, uid); +DROP INDEX IF EXISTS idx_loans_uid; + +ALTER TABLE Battle_Stats DROP CONSTRAINT IF EXISTS battle_stats_pkey, + ADD PRIMARY KEY (chat_id, uid); + +-- Meant for the daily scan for stale dicks, but staleness is not a rare property here: nine of +-- every ten positive dicks are overdue at any moment, so the condition selects almost the whole +-- table and the planner reaches for the chat instead. It is not free to keep, either — `updated_at` +-- changes on every growth, so each write moves the entry. +DROP INDEX IF EXISTS dicks_idx_updated_at; diff --git a/src/config/app.rs b/src/config/app.rs index a61a4fc..672903d 100644 --- a/src/config/app.rs +++ b/src/config/app.rs @@ -4,7 +4,7 @@ use crate::config::env::*; use crate::config::toggles::*; use crate::config::announcements::*; use crate::config::self_destruction::*; -use crate::config::shrink::DailyShrinkConfig; +use crate::config::shrink::{BroadcastConfig, DailyShrinkConfig}; use crate::config::incrementor::IncrementorConfig; use crate::domain::primitives::{AttemptsCount, Bet, DaysCount, Limit, PayoutRatio, Ratio}; use crate::domain::primitives::chat::TelegramChatId; @@ -55,6 +55,18 @@ impl AppConfig { ratio: env_value!("DAILY_SHRINK_RATIO": Ratio), inactivity_days: env_value!("DAILY_SHRINK_INACTIVITY_DAYS": DaysCount, or = 7), ramp_up_days: env_value!("DAILY_SHRINK_RAMP_UP_DAYS": DaysCount, or = 7), + batch_size: env_value!("DAILY_SHRINK_BATCH_SIZE": Limit, or = 100, at_least = 1), + broadcast: BroadcastConfig { + poll_interval: EnvDuration::seconds("DAILY_SHRINK_BROADCAST_POLL_SECONDS").or(5).at_least(1).read(), + batch_size: env_value!("DAILY_SHRINK_BROADCAST_BATCH_SIZE": Limit, or = 200, at_least = 1), + concurrency: env_value!("DAILY_SHRINK_BROADCAST_CONCURRENCY": Limit, or = 16, at_least = 1), + lease: EnvDuration::seconds("DAILY_SHRINK_BROADCAST_LEASE_SECONDS").or(300).at_least(1).read(), + retry_delay: EnvDuration::seconds("DAILY_SHRINK_BROADCAST_RETRY_DELAY_SECONDS").or(60).at_least(1).read(), + max_retry_delay: EnvDuration::seconds("DAILY_SHRINK_BROADCAST_MAX_RETRY_DELAY_SECONDS").or(3600).at_least(1).read(), + max_attempts: env_value!("DAILY_SHRINK_BROADCAST_MAX_ATTEMPTS": AttemptsCount, or = 3, at_least = 1), + max_age: EnvDuration::hours("DAILY_SHRINK_BROADCAST_MAX_AGE_HOURS").or(48).at_least(1).read(), + retention: EnvDuration::days("DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS").or(3).read(), + }, }; let announcements_file = get_env_value_or_default("ANNOUNCEMENTS_FILE", "announcements.yml".to_string()); let self_destruction = SelfDestructionConfig { @@ -74,7 +86,7 @@ impl AppConfig { retry_delay: EnvDuration::seconds("MSG_SELFDESTRUCT_RETRY_DELAY_SECONDS").or(60).at_least(1).read(), max_retry_delay: EnvDuration::seconds("MSG_SELFDESTRUCT_MAX_RETRY_DELAY_SECONDS").or(3600).at_least(1).read(), max_attempts: env_value!("MSG_SELFDESTRUCT_MAX_ATTEMPTS": AttemptsCount, or = 3, at_least = 1), - retention: EnvDuration::minutes("MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_MINUTES").or(1440).read(), + retention: EnvDuration::days("MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS").or(1).read(), }; let support_chat_id = get_optional_chat_id("SUPPORT_CHAT_ID"); Self { diff --git a/src/config/env.rs b/src/config/env.rs index 6ab9e8d..e29d2a0 100644 --- a/src/config/env.rs +++ b/src/config/env.rs @@ -136,6 +136,16 @@ impl<'a> EnvDuration<'a> { Self::of(key, 60) } + /// The variable holds whole hours. + pub fn hours(key: &'a str) -> Self { + Self::of(key, 60 * 60) + } + + /// The variable holds whole days. + pub fn days(key: &'a str) -> Self { + Self::of(key, 60 * 60 * 24) + } + fn of(key: &'a str, seconds_per_unit: u64) -> Self { Self { units: EnvValue::of(key), seconds_per_unit } } diff --git a/src/config/shrink.rs b/src/config/shrink.rs index 41666a5..a8df44b 100644 --- a/src/config/shrink.rs +++ b/src/config/shrink.rs @@ -1,12 +1,46 @@ -use crate::domain::primitives::{DaysCount, Ratio}; +use std::time::Duration; +use crate::domain::primitives::{AttemptsCount, DaysCount, Limit, Ratio}; use domain_types::literal; -/// Tuning for the daily job that shrinks dicks neglected for a while (issue #15). +/// Tuning for the daily job that shrinks dicks neglected for a while (issue #15), and for the +/// worker that delivers the summaries it owes (issue #154). #[derive(Clone, Default)] pub struct DailyShrinkConfig { pub ratio: Ratio, pub inactivity_days: DaysCount, pub ramp_up_days: DaysCount, + /// How many chats one shrinking statement takes on. It bounds both the rows the statement locks + /// and the ones a failure costs, so a `/grow` sent at midnight waits behind one batch rather + /// than behind every stale dick in the database. + pub batch_size: Limit, + pub broadcast: BroadcastConfig, +} + +/// Tuning for the worker that sends the queued shrink summaries. +#[derive(Clone)] +pub struct BroadcastConfig { + /// How often the worker looks for the summaries whose time has come. + pub poll_interval: Duration, + /// How many summaries one run of the worker claims. + pub batch_size: Limit, + /// How many of them it sends at once. What one run gets through is this many messages per round + /// trip to Telegram, so this is the knob for throughput and `batch_size` only bounds how much a + /// run claims. + pub concurrency: Limit, + /// How long a claimed batch stays out of every other worker's reach. + pub lease: Duration, + /// How long a summary rests after a failure that is worth another attempt. + pub retry_delay: Duration, + /// The longest a summary may rest between two attempts, however many have failed. + pub max_retry_delay: Duration, + /// How many attempts a summary gets before the row is marked `failed` and left alone. + pub max_attempts: AttemptsCount, + /// How old a summary may get before it stops being worth sending. Yesterday's list of shrinks + /// is still news in a chat that reads once a day; last week's is noise. + pub max_age: Duration, + /// How long a finished row is kept before the cleaning process removes it. Zero keeps them for + /// ever, which is what makes the queue's own history readable. + pub retention: Duration, } impl DailyShrinkConfig { @@ -16,3 +50,19 @@ impl DailyShrinkConfig { self.ratio > literal!(Ratio = 0.0) && self.inactivity_days.value() > 0 } } + +impl Default for BroadcastConfig { + fn default() -> Self { + Self { + poll_interval: Duration::from_secs(5), + batch_size: Limit::new(200), + concurrency: Limit::new(16), + lease: Duration::from_mins(5), + retry_delay: Duration::from_mins(1), + max_retry_delay: Duration::from_hours(1), + max_attempts: AttemptsCount::new(3), + max_age: Duration::from_hours(48), + retention: Duration::from_hours(72), + } + } +} diff --git a/src/domain/primitives/count.rs b/src/domain/primitives/count.rs index b00a539..256ac54 100644 --- a/src/domain/primitives/count.rs +++ b/src/domain/primitives/count.rs @@ -69,6 +69,26 @@ where i64: sqlx::Decode<'r, DB> } } +/// Counts of the same thing add up — a total over several batches is still a count of `T`. It +/// saturates like every other domain number, so a total can't wrap into a smaller one. +/// +/// Addition is the only operation here. Subtraction would saturate at zero, which turns a +/// difference that was never supposed to go negative into a plausible-looking `0` instead of a +/// failure, and nothing asks for it; a count times a count isn't a count at all. +impl std::ops::Add for Count { + type Output = Self; + + fn add(self, other: Self) -> Self { + Self::new(self.value.saturating_add(other.value)) + } +} + +impl std::ops::AddAssign for Count { + fn add_assign(&mut self, other: Self) { + *self = *self + other; + } +} + impl Deref for Count { type Target = u64; diff --git a/src/domain/primitives/id/mod.rs b/src/domain/primitives/id/mod.rs index 1753b2b..fa7cf13 100644 --- a/src/domain/primitives/id/mod.rs +++ b/src/domain/primitives/id/mod.rs @@ -8,7 +8,8 @@ use crate::*; id!( LoanId, UserId, - ScheduledDeletionId + ScheduledDeletionId, + ScheduledBroadcastId ); #[domain_type] diff --git a/src/error_handler.rs b/src/error_handler.rs index 6fc23bb..410ba3a 100644 --- a/src/error_handler.rs +++ b/src/error_handler.rs @@ -3,39 +3,33 @@ use std::sync::Arc; use futures::future::BoxFuture; use teloxide::RequestError; use teloxide::error_handlers::ErrorHandler; -use crate::metrics::TELEGRAM_REQUEST_ERRORS; - -/// An [`ErrorHandler`] that logs like teloxide's `LoggingErrorHandler` but also feeds the -/// `telegram_request_errors_total` metric, classifying each [`RequestError`] by kind so that a -/// spike of `connect`/`timeout` errors (the DPI/ТСПУ signal) becomes visible in Prometheus. +/// An [`ErrorHandler`] that logs like teloxide's `LoggingErrorHandler`, but joins the whole cause +/// chain onto one line and says which part of the dispatcher the error came from. /// /// It handles both error types that flow through the dispatcher: the boxed errors returned by -/// handlers (a [`RequestError`] — e.g. a failed `sendMessage` — is counted; anything else, like a -/// DB error, is only logged) and a bare [`RequestError`] from an update listener (e.g. failing -/// `getUpdates` when polling). -pub struct MetricsErrorHandler { +/// handlers and a bare [`RequestError`] from an update listener (e.g. failing `getUpdates` when +/// polling). Neither is counted here — `telegram_request_errors_total` is written by +/// [`crate::telegram_observer`], which sees every request rather than only the ones that reach a +/// dispatcher. +pub struct ContextLoggingErrorHandler { text: String, } -impl MetricsErrorHandler { +impl ContextLoggingErrorHandler { pub fn new(text: impl Into) -> Arc { Arc::new(Self { text: text.into() }) } } -impl ErrorHandler> for MetricsErrorHandler { +impl ErrorHandler> for ContextLoggingErrorHandler { fn handle_error(self: Arc, error: Box) -> BoxFuture<'static, ()> { - if let Some(request_error) = error.downcast_ref::() { - TELEGRAM_REQUEST_ERRORS.record(classify(request_error)); - } tracing::error!(context = %self.text, error = %chain(error.as_ref()), "an error reached the error handler"); Box::pin(async {}) } } -impl ErrorHandler for MetricsErrorHandler { +impl ErrorHandler for ContextLoggingErrorHandler { fn handle_error(self: Arc, error: RequestError) -> BoxFuture<'static, ()> { - TELEGRAM_REQUEST_ERRORS.record(classify(&error)); tracing::error!(context = %self.text, error = %chain(&error), "an error reached the error handler"); Box::pin(async {}) } diff --git a/src/handlers/rights.rs b/src/handlers/rights.rs index aa8cab4..6ad5fb3 100644 --- a/src/handlers/rights.rs +++ b/src/handlers/rights.rs @@ -8,12 +8,13 @@ //! The one right tracked here is deleting other members' messages. use autometrics::autometrics; -use teloxide::types::{ChatId, ChatMemberUpdated}; +use teloxide::types::{ChatId, ChatMember, ChatMemberKind, ChatMemberUpdated}; use std::time::Duration; use crate::cache::{Cache, CacheKey}; use crate::config::AppConfig; use crate::domain::primitives::chat::TelegramChatId; use crate::metrics; +use crate::repo::Repositories; /// What the cache last knew about the bot's right to delete messages here, or `None` when nothing /// is known. @@ -48,7 +49,7 @@ pub async fn remember_deletion_right(cache: &Cache, chat_id: ChatId, may_delete: /// demoted or removed, so the write is rare whatever the bot's traffic. #[autometrics] #[tracing::instrument(skip_all, fields(chat_id = upd.chat.id.0))] -pub async fn remember_bot_rights(upd: ChatMemberUpdated, cache: Cache, config: AppConfig) { +pub async fn remember_bot_rights(upd: ChatMemberUpdated, cache: Cache, config: AppConfig, repos: Repositories) { let Some(may_delete) = right_to_remember(&upd) else { return }; @@ -56,6 +57,33 @@ pub async fn remember_bot_rights(upd: ChatMemberUpdated, cache: Cache, config: A tracing::info!(may_delete, "the bot's rights in the chat have changed"); } remember_deletion_right(&cache, upd.chat.id, may_delete, config.caches.bot_admin).await; + + if may_post_again(&upd) { + let chat_id = TelegramChatId::from(upd.chat.id); + // Best-effort: a chat that stays marked merely waits for the next command in it, which is + // what used to be the only way back. + match repos.chats.clear_unreachable(&chat_id).await { + Ok(true) => tracing::info!("the bot may post to the chat again"), + Ok(false) => {}, + Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't clear the unreachable mark of the chat"), + } + } +} + +/// Whether this update is the moment the bot regained the right to post here — added back, or +/// un-muted by an administrator. Both arrive as a `my_chat_member` update, which is why nothing has +/// to poll and why waiting for a command in the chat was never the right signal. +fn may_post_again(upd: &ChatMemberUpdated) -> bool { + !may_post(&upd.old_chat_member) && may_post(&upd.new_chat_member) +} + +/// Whether the bot could send a message with that status. Being present is enough for every status +/// but `restricted`, which is the muted one and carries the answer as a field of its own. +fn may_post(member: &ChatMember) -> bool { + match &member.kind { + ChatMemberKind::Restricted(restricted) => restricted.is_member && restricted.can_send_messages, + kind => kind.is_present(), + } } /// What to remember for this update, or `None` for a chat nothing is ever cleaned up in. @@ -167,6 +195,59 @@ mod test { assert_eq!(right_to_remember(&upd), Some(false)); } + /// A muted bot, which is one of the two ways a chat gets marked unreachable in the first place. + fn muted(can_send: bool) -> serde_json::Value { + serde_json::json!({ + "status": "restricted", + "user": bot(), + "until_date": 0, + "is_member": true, + "can_send_messages": can_send, + "can_send_audios": false, + "can_send_documents": false, + "can_send_photos": false, + "can_send_videos": false, + "can_send_video_notes": false, + "can_send_voice_notes": false, + "can_send_polls": false, + "can_send_other_messages": false, + "can_add_web_page_previews": false, + "can_change_info": false, + "can_invite_users": false, + "can_pin_messages": false, + "can_manage_topics": false, + }) + } + + #[test] + fn being_added_back_lets_the_chat_be_reached_again() { + let upd = updated(supergroup(), left(), member()); + assert!(may_post_again(&upd)); + } + + #[test] + fn being_unmuted_lets_the_chat_be_reached_again() { + let upd = updated(supergroup(), muted(false), muted(true)); + assert!(may_post_again(&upd)); + } + + /// The mark is only ever taken off, never put on here: losing the right is what the failed send + /// finds out, and guessing at it from a status change would take a chat away on a demotion that + /// says nothing about posting. + #[test] + fn losing_the_right_is_not_a_reason_to_clear_anything() { + assert!(!may_post_again(&updated(supergroup(), member(), left()))); + assert!(!may_post_again(&updated(supergroup(), muted(true), muted(false)))); + } + + /// A promotion changes what the bot may do, but it could already post, so nothing about + /// reachability has changed and the mark (if any) was about something else. + #[test] + fn a_promotion_alone_clears_nothing() { + let upd = updated(supergroup(), member(), admin(true)); + assert!(!may_post_again(&upd)); + } + #[test] fn a_private_chat_is_never_of_interest() { let upd = updated(private(), member(), admin(true)); diff --git a/src/handlers/shrink.rs b/src/handlers/shrink.rs index f179b5b..d2a976b 100644 --- a/src/handlers/shrink.rs +++ b/src/handlers/shrink.rs @@ -7,12 +7,12 @@ use rust_i18n::t; use teloxide::Bot; use teloxide::types::{CallbackQuery, InlineKeyboardButton, InlineKeyboardMarkup}; use crate::config::AppConfig; -use crate::domain::primitives::{LanguageCode, Length, Offset, Page, UserId, Username}; +use crate::domain::primitives::{LanguageCode, Offset, Page}; use crate::domain::primitives::chat::ChatIdKind; use crate::handlers::{answer_callback_feature_disabled, FromRefs, HandlerDeps, HandlerResult}; use crate::handlers::utils::callbacks; use crate::handlers::utils::callbacks::{CallbackDataWithPrefix, InvalidCallbackData, InvalidCallbackDataBuilder}; -use crate::repo::{AdjacentDates, RecentShrink, Repositories, ShrinkEvent}; +use crate::repo::{AdjacentDates, RecentShrink, Repositories}; pub(crate) struct ShrinksPage { pub lines: String, @@ -41,29 +41,6 @@ impl ShrinkView { } } -/// Lets a page render from either a fresh [`RecentShrink`] query or the [`ShrinkEvent`]s the daily -/// job already holds, so the broadcast's page 0 needs no query at all. -pub(crate) trait ShrinkLine { - fn uid(&self) -> UserId; - fn owner_name(&self) -> &Username; - fn lost_length(&self) -> Length; - fn length(&self) -> Length; -} - -impl ShrinkLine for RecentShrink { - fn uid(&self) -> UserId { self.uid } - fn owner_name(&self) -> &Username { &self.owner_name } - fn lost_length(&self) -> Length { self.lost_length } - fn length(&self) -> Length { self.length } -} - -impl ShrinkLine for ShrinkEvent { - fn uid(&self) -> UserId { self.uid } - fn owner_name(&self) -> &Username { &self.owner_name } - fn lost_length(&self) -> Length { self.lost_length } - fn length(&self) -> Length { self.new_length } -} - /// Callback payload of a shrink list's "prev/next page" and "prev/next day" buttons. Wire format: /// `shrink:::`. Carrying the date (rather than a relative day window) is /// what makes the broadcast immune to drift: a notification's buttons always re-render the day it @@ -99,8 +76,8 @@ impl TryFrom for ShrinkCallbackData { } } -pub(crate) fn render_shrinks_page( - rows: &[T], +pub(crate) fn render_shrinks_page( + rows: &[RecentShrink], config: &AppConfig, lang_code: &LanguageCode, view: ShrinkView, @@ -116,8 +93,8 @@ pub(crate) fn render_shrinks_page( let lines = rows.iter() .take(usize::from(config.top_limit)) .map(|s| { - let name = s.owner_name().escaped(); - t!(&line_key, locale = lang_code, uid = s.uid(), name = name, lost = s.lost_length(), length = s.length()) + let name = s.owner_name.escaped(); + t!(&line_key, locale = lang_code, uid = s.uid, name = name, lost = s.lost_length, length = s.length) }) .collect::>() .join("\n"); diff --git a/src/main.rs b/src/main.rs index 1c67919..d474d01 100644 --- a/src/main.rs +++ b/src/main.rs @@ -42,7 +42,7 @@ use crate::handlers::{CleanupCommands, DickCommands, DickOfDayCommands, ImportCo use crate::handlers::pvp::{BattleCommands, BattleCommandsNoArgs}; use crate::handlers::stats::StatsCommands; use crate::handlers::utils::locks::LockCallbackServiceFacade; -use crate::error_handler::MetricsErrorHandler; +use crate::error_handler::ContextLoggingErrorHandler; use crate::repo::Repositories; use crate::users::LanguageService; @@ -175,8 +175,10 @@ async fn main() -> Result<(), Box> { // one would count a second budget and let twice as much through. // TODO: [#153] Use a common `Throttle` object shared between handlers and schedulers let throttled_bot = scheduler::throttled(bot.clone(), config::ThrottleConfig::from_env()); - scheduler::spawn_daily_shrink(throttled_bot.clone(), repos.clone(), language_service.clone(), - topic_policy.clone(), app_config.clone()); + scheduler::spawn_daily_shrink(repos.clone(), app_config.clone()); + scheduler::spawn_broadcast_worker(throttled_bot.clone(), repos.clone(), language_service.clone(), + topic_policy.clone(), app_config.clone()); + scheduler::spawn_broadcast_cleaner(repos.clone(), app_config.clone()); scheduler::spawn_deletion_worker(throttled_bot, repos.clone(), cache.clone(), app_config.clone()); scheduler::spawn_deletion_cleaner(repos.clone(), app_config.clone()); reload::spawn_reload_on_sighup(repos.announcements.clone(), ban_list.clone()); @@ -211,7 +213,7 @@ async fn main() -> Result<(), Box> { let error_handler = LoggingErrorHandler::with_custom_text("An error from the update listener"); let mut dispatcher = Dispatcher::builder(bot, handler) .default_handler(ignore_unknown_updates) - .error_handler(MetricsErrorHandler::new("An error in a handler")) + .error_handler(ContextLoggingErrorHandler::new("An error in a handler")) .dependencies(deps) .build(); let bot_fut = dispatcher.dispatch_with_listener(listener, error_handler); @@ -237,10 +239,10 @@ async fn main() -> Result<(), Box> { let bot_fut = tokio::spawn(metrics::TASK_POLLING_DISPATCHER.instrument(async move { let listener = polling_default(bot.clone()).await; - let listener_error_handler = MetricsErrorHandler::new("An error from the update listener"); + let listener_error_handler = ContextLoggingErrorHandler::new("An error from the update listener"); Dispatcher::builder(bot, handler) .default_handler(ignore_unknown_updates) - .error_handler(MetricsErrorHandler::new("An error in a handler")) + .error_handler(ContextLoggingErrorHandler::new("An error in a handler")) .dependencies(deps) .enable_ctrlc_handler() .build() diff --git a/src/metrics.rs b/src/metrics.rs index 822c04c..3937ec7 100644 --- a/src/metrics.rs +++ b/src/metrics.rs @@ -8,7 +8,7 @@ use tokio_metrics_collector::TaskMonitor; use domain_types::traits::SaturatingInto; use crate::config::MessageGroup; use crate::domain::primitives::{Count, SupportedLanguage}; -use crate::repo::{ChatMigrationOutcome, DeletionState, MessageKind, ScheduledDeletion}; +use crate::repo::{BroadcastState, ChatMigrationOutcome, DeletionState, MessageKind, ScheduledDeletion}; /// Additional metrics of our own are registered into this registry by the constructors below. static REGISTRY: Lazy = Lazy::new(prometheus::Registry::new); @@ -91,6 +91,16 @@ pub static ANNOUNCEMENT_SHOWN: Lazy = Lazy::new(|| pub static CHAT_MIGRATION: Lazy = Lazy::new(|| ChatMigrationCounter::new("chat_migration_total", "count of group to supergroup migrations the bot witnessed, by outcome: migrated when the chat came across whole, migrated_unanchored when it came across but left its inline half behind, untraceable when it wasn't known by its old id at all, conflict when both ids already had a row of their own")); pub static DAILY_SHRINK: Lazy = Lazy::new(DailyShrinkCounters::new); +pub static DAILY_SHRINK_LAST_RUN_TIMESTAMP: Lazy = Lazy::new(|| + Gauge::new("daily_shrink_last_run_timestamp_seconds", "the UTC midnight the last logged shrink belongs to, as a Unix timestamp. Read from the database rather than counted in this process, so it survives a restart: alert when time() minus this passes 26 hours")); +pub static DAILY_SHRINK_BROADCAST_PENDING: Lazy = Lazy::new(|| + Gauge::new("daily_shrink_broadcast_pending", "number of shrink summaries the chats are still owed; a number that only grows means the worker stopped draining the queue")); +pub static DAILY_SHRINK_BROADCAST_BATCH_SIZE: Lazy = Lazy::new(|| + Histogram::new("daily_shrink_broadcast_batch_size", + "how many summaries one run of the worker took. Read it together with the duration of that run: short batches and long runs mean Telegram is slow, while batches that reach daily_shrink_broadcast_batch_limit mean the queue is full", + &[0.0, 1.0, 5.0, 10.0, 25.0, 50.0, 100.0, 250.0, 500.0, 1000.0])); +pub static DAILY_SHRINK_BROADCAST_BATCH_LIMIT: Lazy = Lazy::new(|| + Gauge::new("daily_shrink_broadcast_batch_limit", "the value of DAILY_SHRINK_BROADCAST_BATCH_SIZE, so that a graph can tell a full batch from a small one without knowing the setting")); pub static TELEGRAM_REQUEST_ERRORS: Lazy = Lazy::new(|| TelegramRequestErrorCounters::new("telegram_request_errors_total", "count of failed requests to the Telegram Bot API, split by kind (connect/timeout/network/api/rate_limited/other). A spike of connect/timeout is the DPI-stalling signal; rate_limited means Telegram asked the bot to slow down, so the THROTTLE_* limits are set too high")); pub static TELEGRAM_REQUEST_DURATION: Lazy = Lazy::new(|| @@ -114,6 +124,8 @@ pub static TASK_WEBHOOK_SERVER: Lazy = Lazy::new(|| task_monitor("w pub static TASK_POLLING_DISPATCHER: Lazy = Lazy::new(|| task_monitor("polling_dispatcher")); pub static TASK_METRICS_SERVER: Lazy = Lazy::new(|| task_monitor("metrics_http_server")); pub static TASK_DAILY_SHRINK: Lazy = Lazy::new(|| task_monitor("daily_shrink")); +pub static TASK_DAILY_SHRINK_BROADCAST: Lazy = Lazy::new(|| task_monitor("daily_shrink_broadcast")); +pub static TASK_DAILY_SHRINK_BROADCAST_CLEANING: Lazy = Lazy::new(|| task_monitor("daily_shrink_broadcast_cleaning")); pub static TASK_SELF_DESTRUCTION: Lazy = Lazy::new(|| task_monitor("self_destruction")); pub static TASK_SELF_DESTRUCTION_CLEANING: Lazy = Lazy::new(|| task_monitor("self_destruction_cleaning")); pub static TASK_USER_SERVICE_CACHE_CLEANUP: Lazy = Lazy::new(|| task_monitor("user_service_cache_cleanup")); @@ -329,6 +341,11 @@ impl Gauge { /// A gauge is a `float64` on the wire whatever is put in it; `IntGauge` holds an `i64` only /// to keep the arithmetic exact in the process. + /// + /// Takes a bare `i64` rather than a conversion: `domain_types` implements `SaturatingInto` + /// only for the pairs that can lose something, so a caller already holding an `i64` — a Unix + /// timestamp, say — could not satisfy such a bound at all. The narrowing is named where it + /// happens instead. pub fn set(&self, value: i64) { self.0.set(value) } @@ -766,37 +783,42 @@ impl ChatMigrationCounter { } } -/// Counters of the daily shrink job: the runs, the shrunk dicks, and the sent summaries. -/// Without them the job is visible in the logs only. +/// Counters of the daily shrink job: the runs, the shrunk dicks, and the summaries the chats are +/// owed. Without them the job is visible in the logs only. /// -/// Alert on `daily_shrink_run_total` when it stops growing for more than 26 hours. That means the -/// scheduler died: it is a detached task and it stops for good if it can't compute the next -/// wake-up time (see `spawn_daily_shrink`). A day with nothing to shrink still counts as a run, -/// under the `empty` label, so a quiet day doesn't look like a dead scheduler. +/// Whether the scheduler is alive is answered by `daily_shrink_last_run_timestamp_seconds` rather than by +/// any of these: a counter that moves once a day reads zero both when nothing happened and when +/// nobody scraped it before the process restarted, and nothing afterwards tells the two apart. pub struct DailyShrinkCounters { runs: CounterVec, victims: CounterVec, broadcasts: CounterVec, + retries: Counter, } impl DailyShrinkCounters { fn new() -> Self { let runs = CounterVec::new("daily_shrink_run_total", - "count of daily shrink runs by outcome: succeeded when dicks were shrunk, empty when there was nothing to shrink today, failed when the shrinking statement itself errored", &["outcome"]); + "count of daily shrink runs by outcome: succeeded when dicks were shrunk, empty when there was nothing to shrink today, failed when at least one batch of the run errored", &["outcome"]); let victims = CounterVec::new("daily_shrink_victims_total", "count of dicks shrunk, by how their owners get to hear about it: broadcast when their chat can be messaged, inline_only when it can't and the shrinks command is the only way to see it, unreachable when the bot can't post to their chat anymore", &["delivery"]); let broadcasts = CounterVec::new("daily_shrink_broadcast_total", - "count of per-chat shrink summaries by outcome: sent, failed when Telegram rejected the message, unreachable when it rejected it because the bot can't post to that chat at all (which marks the chat), and skipped for chats already marked and not tried again (one sample per chat, not per victim)", &["outcome"]); + "count of per-chat shrink summaries by outcome, one sample per chat and not per victim: sent, unreachable when Telegram rejected it because the bot can't post to that chat at all (which marks the chat), expired when it waited until it stopped being worth sending, failed when every attempt failed, and skipped for chats already marked and never queued", &["outcome"]); + let retries = Counter::new("daily_shrink_broadcast_retries_total", + "count of failed attempts to send a summary that were worth another one; not an outcome, so the outcomes above still add up to the number of summaries"); for outcome in ["succeeded", "empty", "failed"] { runs.counter(&[outcome]); } for delivery in ["broadcast", "inline_only", "unreachable"] { victims.counter(&[delivery]); } - for outcome in ["sent", "failed", "unreachable", "skipped"] { - broadcasts.counter(&[outcome]); + // The four terminal states, spelled the way the table spells them, plus the one ending that + // never reaches the queue at all. + for state in BroadcastState::TERMINAL { + broadcasts.counter(&[&state.to_string()]); } - Self { runs, victims, broadcasts } + broadcasts.counter(&["skipped"]); + Self { runs, victims, broadcasts, retries } } /// A run that shrank at least one dick. @@ -830,26 +852,19 @@ impl DailyShrinkCounters { self.victims.counter(&["unreachable"]).inc_by(count) } - /// One chat's summary delivered. - pub fn broadcast_sent(&self) { - self.broadcasts.counter(&["sent"]).inc() - } - - /// One chat's summary was not delivered. Its members can still use the shrinks command. - /// - /// A transient failure: the same chat is tried again tomorrow. Watch this one — it used to - /// carry the permanent failures too, which kept it growing forever. - pub fn broadcast_failed(&self) { - self.broadcasts.counter(&["failed"]).inc() + /// One summary reached a state it never leaves. Counted where the row is written, so the table + /// and this counter can't say different things. + pub fn broadcast_finished(&self, state: BroadcastState) { + self.broadcasts.counter(&[&state.to_string()]).inc() } - /// One chat's summary was rejected because the bot can't post there at all, so the chat has - /// just been marked and won't be tried again until it comes back. - pub fn broadcast_unreachable(&self) { - self.broadcasts.counter(&["unreachable"]).inc() + /// One attempt failed for a reason worth another attempt. Not an ending: the summary is counted + /// again later, under whatever it does end as. + pub fn broadcast_retried(&self) { + self.retries.inc() } - /// `count` chats weren't even tried: they had already been marked unreachable. + /// `count` chats were never queued: they had already been marked unreachable. pub fn broadcast_skipped(&self, count: u64) { self.broadcasts.counter(&["skipped"]).inc_by(count) } @@ -1056,7 +1071,7 @@ mod tests { let expected = [ ("daily_shrink_run_total", "outcome", ["succeeded", "empty", "failed"].as_slice()), ("daily_shrink_victims_total", "delivery", ["broadcast", "inline_only", "unreachable"].as_slice()), - ("daily_shrink_broadcast_total", "outcome", ["sent", "failed", "unreachable", "skipped"].as_slice()), + ("daily_shrink_broadcast_total", "outcome", ["sent", "unreachable", "expired", "failed", "skipped"].as_slice()), ]; for (metric, label, values) in expected { for value in values { diff --git a/src/observability.rs b/src/observability.rs index f4bbd86..3822f33 100644 --- a/src/observability.rs +++ b/src/observability.rs @@ -2,10 +2,10 @@ use std::collections::HashMap; use std::error::Error; use opentelemetry::global; use opentelemetry::trace::TracerProvider; -use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge; +use opentelemetry_appender_tracing::layer::{OpenTelemetryTracingBridge, TracingSpanAttributes}; use opentelemetry_sdk::Resource; use opentelemetry_otlp::{LogExporter, SpanExporter, WithExportConfig, WithHttpConfig}; -use opentelemetry_sdk::logs::SdkLoggerProvider; +use opentelemetry_sdk::logs::{SdkLogger, SdkLoggerProvider}; use opentelemetry_sdk::trace::SdkTracerProvider; use tracing_subscriber::filter::{filter_fn, FilterExt}; use tracing_subscriber::{Layer, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; @@ -55,6 +55,10 @@ impl Telemetry { /// different protocols. Trace and span ids are attached to the exported records by the SDK itself, /// which is why the console lines carry no ids: without the infrastructure there is nothing to /// match them against anyway. +/// +/// An exported record also carries the fields of every span it was written inside, from the root +/// down, so a value a log message keeps out of its text is searchable all the same. The nearer +/// span wins where two of them name the same field. pub fn init_tracing() -> Result> { let spans_exported = endpoint(TRACES_ENDPOINT_VAR).is_some(); let tracer_provider = build_tracer_provider()?; @@ -74,7 +78,7 @@ pub fn init_tracing() -> Result> { let filter = EnvFilter::from_default_env() .and(filter_fn(|metadata| !NEVER_EXPORTED_TARGETS.iter() .any(|target| metadata.target().starts_with(target)))); - OpenTelemetryTracingBridge::new(provider).with_filter(filter) + build_logs_bridge(provider).with_filter(filter) }); let logs_exported = logs_layer.is_some(); @@ -148,6 +152,19 @@ fn build_logger_provider(endpoint: String) -> Result OpenTelemetryTracingBridge { + OpenTelemetryTracingBridge::builder(provider) + .with_tracing_span_attributes(TracingSpanAttributes::all()) + .build() +} + fn endpoint(variable: &str) -> Option { std::env::var(variable).ok().filter(|value| !value.is_empty()) } @@ -176,9 +193,13 @@ mod tests { "victoria-logs", "victoriametrics/victoria-logs", "latest", VICTORIA_LOGS_PORT, &[]) .with_settle_millis(500); - /// The record must carry the ids of the span it was written in, put there by the SDK. Everything - /// here is the real pipeline: the tracing bridge, the OTLP/HTTP exporter, and the same log database - /// the server runs. The fields must survive as fields, not as text inside the message. + /// The record must carry the ids of the span it was written in, put there by the SDK, and the + /// fields of that span. Everything here is the real pipeline: the tracing bridge, the OTLP/HTTP + /// exporter, and the same log database the server runs. The fields must survive as fields, not + /// as text inside the message. + /// + /// `chat_id` is set on the span and never on an event, so nothing but the span can be carrying + /// it when the assertion finds it. #[tokio::test] async fn an_exported_record_carries_the_trace_id_and_the_fields() { let base_url = victoria_logs().await; @@ -189,12 +210,16 @@ mod tests { let tracer_provider = SdkTracerProvider::builder().build(); let subscriber = tracing_subscriber::registry() .with(tracing_opentelemetry::layer().with_tracer(tracer_provider.tracer("test"))) - .with(OpenTelemetryTracingBridge::new(&logger_provider)); + .with(build_logs_bridge(&logger_provider)); + + // The container outlives the run, so a fixed id could be matched in an earlier run's + // records and the assertion would hold whether or not this run's fields arrived. + let chat_id = -i64::from(std::process::id()); let trace_id = tracing::subscriber::with_default(subscriber, || { - let span = tracing::info_span!("a_handler"); + let span = tracing::info_span!("a_handler", chat_id); let _entered = span.enter(); - tracing::info!(chat_id = -100500, "a message from the test"); + tracing::info!("a message from the test"); // The shape sqlx logs a finished query in: fields only, no message. tracing::info!(summary = "SELECT Dicks …", rows_returned = 1); span.context().span().span_context().trace_id().to_string() @@ -205,7 +230,7 @@ mod tests { let logs = query_logs(&base_url, &trace_id).await; assert!(logs.contains("a message from the test"), "the record is missing from:\n{logs}"); assert!(logs.contains(&trace_id), "the trace id {trace_id} is missing from:\n{logs}"); - assert!(logs.contains("-100500"), "the chat_id field is missing from:\n{logs}"); + assert!(logs.contains(&chat_id.to_string()), "the chat_id of the span is missing from:\n{logs}"); assert!(logs.contains(r#""severity_text":"INFO""#), "the level is missing from:\n{logs}"); // A record without a message takes it from `summary`; see `build_logger_provider`. assert!(logs.contains(r#""_msg":"SELECT Dicks …""#), "the fallback message is missing from:\n{logs}"); diff --git a/src/repo/broadcasts.rs b/src/repo/broadcasts.rs new file mode 100644 index 0000000..2df9085 --- /dev/null +++ b/src/repo/broadcasts.rs @@ -0,0 +1,151 @@ +use autometrics::autometrics; +use anyhow::Context; +use chrono::{DateTime, NaiveDate, Utc}; +use crate::domain::primitives::{AttemptsCount, Count, Limit, ScheduledBroadcastId}; +use crate::domain::primitives::chat::TelegramChatId; +use crate::repository; + +/// How far a summary got. `Created` is the only actionable one; the rest are terminal and stay in +/// the table until the cleaning process removes them, so that a queue which isn't doing its job can +/// be read rather than guessed at. +#[derive(Clone, Copy, Debug, PartialEq, Eq, sqlx::Type, strum_macros::Display)] +#[strum(serialize_all = "snake_case")] +#[sqlx(type_name = "broadcast_state", rename_all = "snake_case")] +pub enum BroadcastState { + Created, + /// The chat got its summary. + Sent, + /// Telegram says the bot can't post to that chat at all, which marks the chat too. + Unreachable, + /// The summary sat in the queue until it stopped being worth sending. + Expired, + /// Every attempt failed for a reason that looked transient and never stopped being one. + Failed, +} + +impl BroadcastState { + /// The states a row never leaves. What is kept in the table until the cleaning process runs, + /// and what the gauges of [`crate::metrics::SHRINK_BROADCAST_FINISHED`] are split by. + pub const TERMINAL: [Self; 4] = [Self::Sent, Self::Unreachable, Self::Expired, Self::Failed]; +} + +/// A summary a chat is owed, as the worker claims it. +#[derive(Clone, Debug)] +pub struct ScheduledBroadcast { + pub id: ScheduledBroadcastId, + /// Read at claim time rather than stored, so a group that became a supergroup meanwhile is + /// addressed by the id it answers to now. + pub chat_id: TelegramChatId, + pub shrink_date: NaiveDate, + /// When the shrink that owes this summary was committed, which is the summary's age. + pub created_at: DateTime, + /// Attempts that have already failed, which is what the back-off is computed from. + pub attempts: AttemptsCount, +} + +repository!(ScheduledBroadcasts, + /// Takes up to `limit` summaries whose time has come, leasing them until `lease_until`. + /// + /// The lease is what makes the claim exclusive: the row's lock lives only as long as this one + /// statement, while the request it leads to takes far longer. A worker that dies mid-batch + /// leaves its summaries to be claimed again once the lease runs out, rather than for ever. + /// + /// A row whose chat has since lost its Telegram id is finished as failed rather than skipped: + /// the lease runs out, and a row nobody can act on would come back with every tick for ever. + #[autometrics] + #[tracing::instrument(skip_all, fields(limit = %limit))] + pub async fn claim_due(&self, limit: Limit, lease_until: DateTime) -> anyhow::Result> { + let rows = sqlx::query!( + r#"UPDATE Scheduled_Shrink_Broadcasts b SET fire_after = $2 + WHERE b.id IN ( + SELECT id FROM Scheduled_Shrink_Broadcasts + WHERE fire_after <= current_timestamp AND finished_at IS NULL + ORDER BY fire_after + LIMIT $1 + FOR UPDATE SKIP LOCKED + ) + RETURNING b.id AS "id: ScheduledBroadcastId", + (SELECT c.chat_id FROM Chats c WHERE c.id = b.chat_id) AS "chat_id: TelegramChatId", + b.shrink_date, b.created_at, b.attempts AS "attempts!: AttemptsCount""#, + limit as Limit, lease_until + ) + .fetch_all(&self.pool) + .await + .context("couldn't claim the shrink summaries due for broadcasting")?; + + let mut claimed = Vec::with_capacity(rows.len()); + for row in rows { + let Some(chat_id) = row.chat_id else { + tracing::error!(id = %row.id, "a queued shrink summary points at a chat with no Telegram id, giving up on it"); + self.finish(row.id, BroadcastState::Failed).await + .unwrap_or_else(|e| tracing::error!(id = %row.id, error = format!("{e:#}"), + "couldn't give up on the unusable shrink summary")); + continue + }; + claimed.push(ScheduledBroadcast { + id: row.id, + chat_id, + shrink_date: row.shrink_date, + created_at: row.created_at, + attempts: row.attempts, + }); + } + Ok(claimed) + }, + + /// How many summaries are still owed — reported as a gauge, so a queue that stops draining is + /// visible before the chats are. The finished rows are left out: they are history, and counting + /// them would make the gauge grow on its own until the cleaning process runs. + #[autometrics] + #[tracing::instrument(skip_all)] + pub async fn count_pending(&self) -> anyhow::Result> { + sqlx::query_scalar!( + r#"SELECT count(*) AS "count!: Count" + FROM Scheduled_Shrink_Broadcasts WHERE finished_at IS NULL"#) + .fetch_one(&self.pool) + .await + .context("couldn't count the pending shrink summaries") + }, + + /// Counts one failed attempt and pushes the row back by `retry_after`. + #[autometrics] + #[tracing::instrument(skip_all, fields(id = %id))] + pub async fn postpone(&self, id: ScheduledBroadcastId, retry_after: DateTime) -> anyhow::Result { + let attempts = sqlx::query_scalar!( + r#"UPDATE Scheduled_Shrink_Broadcasts SET attempts = attempts + 1, fire_after = $2 + WHERE id = $1 RETURNING attempts AS "attempts!: AttemptsCount""#, + id as ScheduledBroadcastId, retry_after) + .fetch_one(&self.pool) + .await + .context("couldn't postpone the shrink summary")?; + Ok(attempts) + }, + + /// Leaves the row behind in a terminal state instead of dropping it, so that what the worker + /// did — and what it couldn't do — can be read out of the table until the cleaning process + /// takes it away. + #[autometrics] + #[tracing::instrument(skip_all, fields(id = %id, state = %state))] + pub async fn finish(&self, id: ScheduledBroadcastId, state: BroadcastState) -> anyhow::Result<()> { + sqlx::query!( + "UPDATE Scheduled_Shrink_Broadcasts SET state = $2, finished_at = current_timestamp WHERE id = $1", + id as ScheduledBroadcastId, state as BroadcastState) + .execute(&self.pool) + .await + .context("couldn't finish the shrink summary")?; + Ok(()) + }, + + /// Removes the rows that were finished before `older_than`, and says how many went. + #[autometrics] + #[tracing::instrument(skip_all)] + pub async fn delete_finished(&self, older_than: DateTime) -> anyhow::Result { + let result = sqlx::query!( + "DELETE FROM Scheduled_Shrink_Broadcasts WHERE finished_at IS NOT NULL AND finished_at < $1", + older_than) + .execute(&self.pool) + .await + .context("couldn't clean the finished shrink summaries up")?; + Ok(result.rows_affected()) + } +); diff --git a/src/repo/chats.rs b/src/repo/chats.rs index b24bb81..d6ed961 100644 --- a/src/repo/chats.rs +++ b/src/repo/chats.rs @@ -165,8 +165,8 @@ repository!(Chats, with_feature_toggles, .context(format!("couldn't check whether the chat with id = {chat_id} is anchored")) } , - /// Remembers that the bot couldn't post to this chat, so the daily shrink stops trying to - /// broadcast there. Cleared by [`Self::upsert_chat`] on the next command in the chat. + /// Remembers that the bot couldn't post to this chat, so the daily shrink stops queueing + /// summaries for it. /// /// Keyed by the Telegram id: that's what the broadcast holds, and a chat known only by its /// `chat_instance` is never a broadcast target anyway. Updating no row is fine — the chat may @@ -181,6 +181,20 @@ repository!(Chats, with_feature_toggles, .map(|_| ()) .context(format!("couldn't mark the chat with id = {chat_id} as unreachable")) } +, + /// Takes the mark off again, and says whether there was one. Keyed by the Telegram id, so that + /// the moment Telegram says the bot may post here again can clear it — which is the only signal + /// that ever means it: time alone never un-kicks a bot. + #[autometrics] + #[tracing::instrument(skip_all, fields(chat_id = %chat_id))] + pub async fn clear_unreachable(&self, chat_id: &TelegramChatId) -> anyhow::Result { + sqlx::query!("UPDATE Chats SET is_unreachable = false WHERE chat_id = $1 AND is_unreachable", + chat_id as &TelegramChatId) + .execute(&self.pool) + .await + .map(|result| result.rows_affected() > 0) + .context(format!("couldn't clear the unreachable mark of the chat with id = {chat_id}")) + } , #[autometrics] #[tracing::instrument(skip_all, fields(chat_id = %chat_id))] diff --git a/src/repo/deletions.rs b/src/repo/deletions.rs index 55fdf67..d2a5ce3 100644 --- a/src/repo/deletions.rs +++ b/src/repo/deletions.rs @@ -311,294 +311,3 @@ repository!(ScheduledDeletions, Ok(()) } ); - -#[cfg(test)] -mod tests { - use std::time::Duration; - use domain_types::traits::SaturatingInto; - use chrono::Utc; - use super::*; - use crate::repo::test::fresh_db; - - const CHAT_ID: i64 = -1001234567890; - - fn chat_message(message_id: u32) -> DeletionTarget { - DeletionTarget::ChatMessage { - chat_id: TelegramChatId::new(CHAT_ID), - message_id: TelegramMessageId::new(message_id), - } - } - - /// A lease long enough that nothing under test can outlive it. - fn lease() -> DateTime { - Utc::now() + Duration::from_secs(600) - } - - fn due(target: DeletionTarget, kind: MessageKind) -> NewDeletion { - NewDeletion { - target, - kind, - group: MessageGroup::Notice, - lang_code: LanguageCode::new("en".to_owned()), - fire_after: Utc::now() - Duration::from_secs(1), - } - } - - #[tokio::test] - async fn only_the_due_messages_are_claimed() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - - let later = NewDeletion { fire_after: Utc::now() + Duration::from_secs(600), ..due(chat_message(2), MessageKind::Reply) }; - repo.schedule(&[due(chat_message(1), MessageKind::Reply), later]) - .await.expect("couldn't schedule the deletions"); - - let claimed = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed.len(), 1); - assert_eq!(claimed[0].target, chat_message(1)); - assert_eq!(claimed[0].kind, MessageKind::Reply); - assert_eq!(claimed[0].state, DeletionState::Created); - - let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 2); - } - - /// The whole point of the lease: a message being worked on is invisible to everyone else, and - /// nothing here holds a lock long enough to do that on its own. - #[tokio::test] - async fn a_claimed_message_is_not_claimed_again() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - - let claimed = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed.len(), 1); - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert!(claimed_again.is_empty()); - } - - /// A worker that dies mid-batch must not take its messages down with it. - #[tokio::test] - async fn a_message_of_an_expired_lease_comes_back() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - - let expired = Utc::now() - Duration::from_secs(1); - let claimed = repo.claim_due(Limit::new(10), expired).await.expect("couldn't claim the deletions"); - assert_eq!(claimed.len(), 1); - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed_again.len(), 1); - assert_eq!(claimed_again[0].id, claimed[0].id); - } - - #[tokio::test] - async fn an_inline_message_survives_the_round_trip() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - let target = DeletionTarget::InlineMessage(InlineMessageId::new("AgAAAOEcAABzXwsRJ0Cs2A".to_owned())); - - repo.schedule(&[due(target.clone(), MessageKind::Inline)]) - .await.expect("couldn't schedule the deletion"); - - let claimed = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed.len(), 1); - assert_eq!(claimed[0].target, target); - assert_eq!(claimed[0].kind, MessageKind::Inline); - } - - #[tokio::test] - async fn the_same_message_is_scheduled_once() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion again"); - - let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 1); - } - - #[tokio::test] - async fn a_warned_message_comes_back_at_the_end_of_the_grace_period() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - let claimed = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - - repo.mark_warned(claimed[0].id, Utc::now() + Duration::from_secs(600)) - .await.expect("couldn't mark the deletion as warned"); - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert!(claimed_again.is_empty()); - - repo.mark_warned(claimed[0].id, Utc::now() - Duration::from_secs(1)) - .await.expect("couldn't mark the deletion as warned"); - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed_again.len(), 1); - assert_eq!(claimed_again[0].state, DeletionState::Warned); - } - - #[tokio::test] - async fn a_postponed_message_counts_its_attempts() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - let claimed = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - - let attempts = repo.postpone(claimed[0].id, Utc::now() - Duration::from_secs(1)) - .await.expect("couldn't postpone the deletion"); - assert_eq!(attempts, 1); - let attempts = repo.postpone(claimed[0].id, Utc::now() - Duration::from_secs(1)) - .await.expect("couldn't postpone the deletion again"); - assert_eq!(attempts, 2); - - // The count the back-off is computed from has to survive the round trip, or every attempt - // would rest as long as the first. - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert_eq!(claimed_again.len(), 1); - assert_eq!(claimed_again[0].attempts, 2); - } - - /// A finished row stays in the table as the account of what happened, but is out of the - /// worker's way and out of the gauge that says how much work is left. - #[tokio::test] - async fn a_finished_message_is_kept_but_never_claimed() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(chat_message(2), MessageKind::Command)]) - .await.expect("couldn't schedule the deletions"); - let claimed = repo.claim_due(Limit::new(10), Utc::now() - Duration::from_secs(1)) - .await.expect("couldn't claim the deletions"); - assert_eq!(claimed.len(), 2); - - repo.finish(claimed[0].id, DeletionState::Removed).await.expect("couldn't finish the deletion"); - repo.finish(claimed[1].id, DeletionState::Failed).await.expect("couldn't fail the deletion"); - - let claimed_again = repo.claim_due(Limit::new(10), lease()).await.expect("couldn't claim the deletions"); - assert!(claimed_again.is_empty()); - let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 0); - - let mut finished = repo.count_finished().await.expect("couldn't count the finished deletions"); - finished.sort_by_key(|(state, _)| state.to_string()); - assert_eq!(finished, vec![(DeletionState::Failed, Count::::new(1)), (DeletionState::Removed, Count::::new(1))]); - } - - /// Every terminal state has to survive the trip to the database and back, or a row would end up - /// counted under the wrong ending — the two-word one especially, as it is the only place the - /// snake_case spelling of the enum matters. - #[tokio::test] - async fn every_terminal_state_survives_the_round_trip() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - let messages: Vec<_> = (1..=DeletionState::TERMINAL.len()) - .map(|i| due(chat_message(i.saturating_into()), MessageKind::Reply)) - .collect(); - repo.schedule(&messages).await.expect("couldn't schedule the deletions"); - let claimed = repo.claim_due(Limit::new(10), lease()) - .await.expect("couldn't claim the deletions"); - - for (deletion, state) in claimed.iter().zip(DeletionState::TERMINAL) { - repo.finish(deletion.id, state).await.expect("couldn't finish the deletion"); - } - - let finished = repo.count_finished().await.expect("couldn't count the finished deletions"); - for state in DeletionState::TERMINAL { - assert!(finished.contains(&(state, Count::::new(1))), "{state} is missing from {finished:?}"); - } - } - - #[tokio::test] - async fn only_the_finished_rows_are_cleaned_up() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(chat_message(2), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletions"); - let claimed = repo.claim_due(Limit::new(10), lease()) - .await.expect("couldn't claim the deletions"); - repo.finish(claimed[0].id, DeletionState::Failed) - .await.expect("couldn't fail the deletion"); - - // Nothing has been finished for long enough yet. - let removed = repo.delete_finished(Utc::now() - Duration::from_secs(600)) - .await.expect("couldn't clean the deletions up"); - assert_eq!(removed, 0); - - let removed = repo.delete_finished(Utc::now() + Duration::from_secs(600)) - .await.expect("couldn't clean the deletions up"); - assert_eq!(removed, 1); - let pending = repo.count_pending() - .await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 1); - } - - /// A row addressing no message can only be made by hand, around the CHECK constraint that - /// forbids it. It must not be handed to the worker as some empty id it would then spend three - /// attempts on — and it must not keep coming back with every tick either. - #[tokio::test] - async fn a_row_that_addresses_no_message_is_given_up_on() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db.clone()); - sqlx::query!("ALTER TABLE Scheduled_Message_Deletions DROP CONSTRAINT scheduled_message_deletions_check") - .execute(&db).await.expect("couldn't drop the check constraint"); - sqlx::query!("INSERT INTO Scheduled_Message_Deletions (message_kind, message_group, lang_code, fire_after) - VALUES ('reply', 'notice', 'en', current_timestamp - interval '1 minute')") - .execute(&db).await.expect("couldn't insert the malformed row"); - - let claimed = repo.claim_due(Limit::new(10), lease()) - .await.expect("couldn't claim the deletions"); - assert!(claimed.is_empty()); - - let finished = repo.count_finished() - .await.expect("couldn't count the finished deletions"); - assert_eq!(finished, vec![(DeletionState::Failed, Count::::new(1))]); - let claimed_again = repo.claim_due(Limit::new(10), Utc::now()) - .await.expect("couldn't claim the deletions"); - assert!(claimed_again.is_empty()); - } - - /// A removed message is history like any other ending, so its row waits for the cleaning - /// process rather than disappearing with it. - #[tokio::test] - async fn a_removed_message_stays_until_it_is_cleaned_up() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) - .await.expect("couldn't schedule the deletion"); - let claimed = repo.claim_due(Limit::new(10), lease()) - .await.expect("couldn't claim the deletions"); - - repo.finish(claimed[0].id, DeletionState::Removed) - .await.expect("couldn't finish the deletion"); - - let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 0); - let finished = repo.count_finished().await.expect("couldn't count the finished deletions"); - assert_eq!(finished, vec![(DeletionState::Removed, Count::::new(1))]); - - let removed = repo.delete_finished(Utc::now() + Duration::from_secs(600)) - .await.expect("couldn't clean the deletions up"); - assert_eq!(removed, 1); - } - - #[tokio::test] - async fn a_cancelled_message_is_kept() { - let db = fresh_db().await; - let repo = ScheduledDeletions::new(db); - let inline = DeletionTarget::InlineMessage(InlineMessageId::new("AgAAAOEcAABzXwsRJ0Cs2A".to_owned())); - repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(inline.clone(), MessageKind::Inline)]) - .await.expect("couldn't schedule the deletions"); - - repo.cancel(&chat_message(1)).await.expect("couldn't cancel the deletion"); - repo.cancel(&inline).await.expect("couldn't cancel the deletion"); - - let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); - assert_eq!(pending, 0); - } -} diff --git a/src/repo/mod.rs b/src/repo/mod.rs index e960878..5caf288 100644 --- a/src/repo/mod.rs +++ b/src/repo/mod.rs @@ -9,6 +9,7 @@ mod stats; mod shrinks; mod announcements; mod deletions; +mod broadcasts; #[cfg(test)] pub(crate) mod test; @@ -27,6 +28,7 @@ pub use stats::*; pub use shrinks::*; pub use announcements::*; pub use deletions::*; +pub use broadcasts::*; use crate::config; use crate::config::DatabaseConfig; use crate::domain::primitives::chat::ChatIdKind; @@ -44,6 +46,7 @@ pub struct Repositories { pub personal_stats: PersonalStatsRepo, pub shrinks: Shrinks, pub deletions: ScheduledDeletions, + pub broadcasts: ScheduledBroadcasts, } impl Repositories { @@ -60,6 +63,7 @@ impl Repositories { personal_stats: PersonalStatsRepo::new(db_conn.clone()), shrinks: Shrinks::new(db_conn.clone()), deletions: ScheduledDeletions::new(db_conn.clone()), + broadcasts: ScheduledBroadcasts::new(db_conn.clone()), } } } diff --git a/src/repo/shrinks.rs b/src/repo/shrinks.rs index 4380005..deed3db 100644 --- a/src/repo/shrinks.rs +++ b/src/repo/shrinks.rs @@ -1,22 +1,43 @@ use autometrics::autometrics; use anyhow::Context; -use chrono::NaiveDate; -use crate::domain::primitives::{DaysCount, Length, Limit, Offset, Ratio, UserId, Username}; -use crate::domain::primitives::chat::{ChatIdKind, TelegramChatId}; +use chrono::{DateTime, NaiveDate, Utc}; +use crate::domain::primitives::{Count, DaysCount, Length, Limit, Offset, Ratio, UserId, Username}; +use crate::domain::primitives::chat::{ChatIdKind, InternalChatId}; +use crate::repo::Chat; use crate::repository; -/// A single shrink applied during the daily job. Carries the post-shrink length (from the -/// `UPDATE ... RETURNING`) and the nullable messageable Telegram chat id used to address the -/// broadcast — `None` for inline-only chats the bot can't message proactively. -pub struct ShrinkEvent { - pub uid: UserId, - pub owner_name: Username, - pub lost_length: Length, - pub new_length: Length, - pub messageable_chat_id: Option, - /// The bot couldn't post to this chat last time it tried, so the broadcast skips it. Unrelated - /// to `messageable_chat_id`: a chat can be messageable in principle and still unreachable. - pub is_unreachable: bool, +/// What one batch of the daily shrink did. The shrinks themselves are in `Stale_Dick_Shrinks` and +/// the summaries they owe are in `Scheduled_Shrink_Broadcasts`, so nothing but the counts has to +/// travel back: at a million victims a day, the rows would be the run's whole memory footprint. +/// +/// The three delivery counts partition `victims`, and they are what the daily-shrink metrics are +/// split by. A victim is one shrunk dick, not one user: the same person is counted once per chat +/// they play in, which is also how the summaries are addressed. +#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)] +pub struct ShrinkBatchOutcome { + pub victims: Count, + /// Victims whose chat got a row in the broadcast queue. + pub to_broadcast: Count, + /// Victims of chats the bot can't message proactively at all; the `shrinks` command is the only + /// way they get to see it. + pub inline_only: Count, + /// Victims of chats the bot couldn't post to last time it tried. + pub unreachable: Count, + /// Chats that got a row, which is how many messages the broadcast will send. + pub chats_queued: Count, + /// Chats the bot is known to have lost access to, so nothing was queued for them. + pub chats_skipped: Count, +} + +impl std::ops::AddAssign for ShrinkBatchOutcome { + fn add_assign(&mut self, other: Self) { + self.victims += other.victims; + self.to_broadcast += other.to_broadcast; + self.inline_only += other.inline_only; + self.unreachable += other.unreachable; + self.chats_queued += other.chats_queued; + self.chats_skipped += other.chats_skipped; + } } /// The log only stores how much was lost, so `length` (the owner's *current* length) comes from a @@ -37,9 +58,41 @@ pub struct AdjacentDates { } repository!(Shrinks, - /// Shrinks every dick that is still positive and hasn't been grown for `grace_days`, logging - /// each shrink into `Stale_Dick_Shrinks` and returning the events for the broadcast. The whole thing - /// is one statement: Postgres runs the unreferenced `logged` data-modifying CTE to completion. + /// One batch of chats, in id order, for the run to walk. `after` is the last id of the previous + /// batch, so the caller keeps nothing but that number. + /// + /// Deliberately not "the chats that have something to shrink": that question needs a `DISTINCT` + /// over every stale dick in the database — around a million rows aggregated down to a couple of + /// hundred thousand ids — and it excludes about one chat in eight, because nearly every chat has + /// a neglected dick in it. Reading the primary key instead is an index scan, and a batch whose + /// chats turn out to have nothing stale simply shrinks nothing. + #[autometrics] + #[tracing::instrument(skip_all, fields(after = ?after, limit = %limit))] + pub async fn select_chats_batch( + &self, + after: Option, + limit: Limit, + ) -> anyhow::Result> { + sqlx::query_scalar!( + r#"SELECT id AS "id: InternalChatId" FROM Chats + WHERE id > $1 ORDER BY id LIMIT $2"#, + after.unwrap_or(InternalChatId::new(0)) as InternalChatId, limit as Limit) + .fetch_all(&self.pool) + .await + .context("couldn't read a batch of chats to shrink") + }, + + /// Shrinks the stale dicks of `chat_ids`, logs each shrink into `Stale_Dick_Shrinks` and queues + /// one broadcast per chat that can be messaged. The whole thing is one statement: Postgres runs + /// the unreferenced data-modifying CTEs to completion. + /// + /// Queueing in the same statement is the durability of the broadcast: there is no moment at + /// which a shrink is committed and the summary it owes is not. What the queue then does with + /// the row — when to send it, how often to retry — is nobody's business here. + /// + /// Taking the chats as an argument bounds both the locks and the result: the run walks them in + /// batches, so a `/grow` at midnight waits behind one batch instead of behind every victim in + /// the database, and a batch that fails costs its own chats rather than the whole day. /// /// The full `ratio` doesn't apply from day one of staleness: it ramps up linearly over /// `ramp_up_days`, starting at `ratio / ramp_up_days` on the first overdue day and reaching @@ -47,14 +100,15 @@ repository!(Shrinks, /// afterwards) — so neglect is punished gradually rather than with one abrupt cut the moment /// the grace period lapses. `ramp_up_days <= 1` reproduces the old instant-full-ratio behavior. #[autometrics] - #[tracing::instrument(skip_all, fields(ratio = %ratio, grace_days = %grace_days, ramp_up_days = %ramp_up_days))] + #[tracing::instrument(skip_all, fields(chats = chat_ids.len(), ratio = %ratio, grace_days = %grace_days, ramp_up_days = %ramp_up_days))] pub async fn perform_daily_shrink( &self, + chat_ids: &[InternalChatId], ratio: Ratio, grace_days: DaysCount, ramp_up_days: DaysCount, - ) -> anyhow::Result> { - sqlx::query_as!(ShrinkEvent, + ) -> anyhow::Result { + let outcome = sqlx::query_as!(ShrinkBatchOutcome, r#"WITH victims AS ( SELECT d.uid, d.chat_id, LEAST(d.length, GREATEST(1, CEIL(d.length * $1::double precision * LEAST(1.0, @@ -62,28 +116,58 @@ repository!(Shrinks, / GREATEST($3::bigint::int, 1) ))::bigint)) AS loss FROM Dicks d - WHERE d.length > 0 + WHERE d.chat_id = ANY($4) + AND d.length > 0 AND d.updated_at <= current_timestamp - make_interval(days => $2::bigint::int) ), updated AS ( UPDATE Dicks d SET length = d.length - v.loss, bonus_attempts = d.bonus_attempts + 1 FROM victims v WHERE d.uid = v.uid AND d.chat_id = v.chat_id - RETURNING d.uid, d.chat_id, v.loss AS loss, d.length AS new_length + RETURNING d.uid, d.chat_id, v.loss AS loss ), logged AS ( INSERT INTO Stale_Dick_Shrinks (chat_id, uid, lost_length) SELECT chat_id, uid, loss FROM updated + ), + classified AS ( + SELECT u.uid, u.chat_id, c.chat_id IS NOT NULL AS messageable, c.is_unreachable + FROM updated u JOIN Chats c ON c.id = u.chat_id + ), + queued AS ( + INSERT INTO Scheduled_Shrink_Broadcasts (chat_id, shrink_date) + SELECT DISTINCT chat_id, current_date FROM classified + WHERE messageable AND NOT is_unreachable + ON CONFLICT DO NOTHING + RETURNING chat_id ) - SELECT u.uid AS "uid: UserId", usr.name AS "owner_name: Username", - u.loss AS "lost_length!: Length", u.new_length AS "new_length!: Length", - c.chat_id AS "messageable_chat_id: TelegramChatId", c.is_unreachable - FROM updated u - JOIN Users usr USING (uid) - JOIN Chats c ON c.id = u.chat_id"#, - ratio as Ratio, grace_days as DaysCount, ramp_up_days as DaysCount) - .fetch_all(&self.pool) + SELECT count(*) AS "victims!: Count", + count(*) FILTER (WHERE messageable AND NOT is_unreachable) AS "to_broadcast!: Count", + count(*) FILTER (WHERE NOT messageable) AS "inline_only!: Count", + count(*) FILTER (WHERE messageable AND is_unreachable) AS "unreachable!: Count", + (SELECT count(*) FROM queued) AS "chats_queued!: Count", + count(DISTINCT chat_id) FILTER (WHERE messageable AND is_unreachable) AS "chats_skipped!: Count" + FROM classified"#, + ratio as Ratio, grace_days as DaysCount, ramp_up_days as DaysCount, + chat_ids as &[InternalChatId]) + .fetch_one(&self.pool) + .await + .context("couldn't perform the daily shrink")?; + Ok(outcome) + }, + + /// When the last shrink was logged, as the moment of the UTC midnight it belongs to. `None` + /// before the first run ever. + /// + /// Published as a gauge, which is the only shape that answers "is the scheduler still alive?" + /// across a restart: the table remembers, where a counter in this process does not. + #[autometrics] + #[tracing::instrument(skip_all)] + pub async fn get_last_shrink_timestamp(&self) -> anyhow::Result>> { + sqlx::query_scalar!( + r#"SELECT (max(created_at)::timestamp AT TIME ZONE 'UTC') AS "at?" FROM Stale_Dick_Shrinks"#) + .fetch_one(&self.pool) .await - .context("couldn't perform the daily shrink") + .context("couldn't read the time of the last shrink") }, #[autometrics] diff --git a/src/repo/test/announcements.rs b/src/repo/test/announcements.rs index 8886490..30fd215 100644 --- a/src/repo/test/announcements.rs +++ b/src/repo/test/announcements.rs @@ -9,7 +9,7 @@ use crate::repo::test::{dicks, fresh_db, CHAT_ID_KIND}; #[tokio::test] async fn test_configured() { let db = fresh_db().await; - create_chat(&db).await; + seed_chat_with_player(&db).await; // test creation and update for i in 1..=2 { @@ -52,7 +52,7 @@ async fn test_configured_impl(db: &Pool, attempt: u8) { async fn test_no_announcements() { let db = fresh_db().await; let [en, _] = get_languages(); - create_chat(&db).await; + seed_chat_with_player(&db).await; // Ensure we get nothing if properties are not set: @@ -82,7 +82,7 @@ async fn test_no_announcements() { #[tokio::test] async fn test_reload() { let db = fresh_db().await; - create_chat(&db).await; + seed_chat_with_player(&db).await; let [en, _] = get_languages(); let path = write_temp_file("max_shows: 1\ntexts:\n en: before\n"); @@ -116,7 +116,8 @@ fn write_file(path: &str, content: &str) { std::fs::write(path, content).expect("couldn't write the temp file"); } -async fn create_chat(db: &Pool) { +/// A chat with a player in it, which is what an announcement needs to be shown to. +async fn seed_chat_with_player(db: &Pool) { let chat_id_part = CHAT_ID_KIND.clone().into(); dicks::create_user_and_dick_2(db, &chat_id_part, "Ann").await; } diff --git a/src/repo/test/broadcasts.rs b/src/repo/test/broadcasts.rs new file mode 100644 index 0000000..e716ed6 --- /dev/null +++ b/src/repo/test/broadcasts.rs @@ -0,0 +1,221 @@ +use std::time::Duration; +use chrono::Utc; +use sqlx::{Pool, Postgres}; +use crate::repo::{BroadcastState, ScheduledBroadcasts}; +use crate::domain::primitives::Limit; +use crate::domain::primitives::chat::TelegramChatId; +use crate::repo::test::{create_chat, far_future, fresh_db}; + +/// The enqueue is a CTE of the shrinking statement in production; here it is spelled out, so +/// that these tests are about the queue rather than about the shrink. +async fn queue(db: &Pool, internal_chat_id: i64, days_ago: i32) { + sqlx::query!( + "INSERT INTO Scheduled_Shrink_Broadcasts (chat_id, shrink_date, created_at) \ + VALUES ($1, current_date - $2::int, current_timestamp - make_interval(days => $2)) \ + ON CONFLICT DO NOTHING", + internal_chat_id, days_ago) + .execute(db).await.expect("couldn't queue the summary"); +} + +/// What the table says became of each summary. The repository no longer counts this — the queue's +/// history is read by a dashboard panel, not by a gauge — so the tests read it the same way. +async fn finished_states(db: &Pool) -> Vec<(String, i64)> { + sqlx::query!(r#"SELECT state::text AS "state!", count(*) AS "count!" FROM Scheduled_Shrink_Broadcasts + WHERE finished_at IS NOT NULL GROUP BY state ORDER BY 1"#) + .fetch_all(db).await.expect("couldn't count the finished summaries") + .into_iter().map(|row| (row.state, row.count)).collect() +} + +#[tokio::test] +async fn a_queued_summary_is_claimed_with_the_chat_it_is_owed_to() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + let internal_id = create_chat(&db, -1001234567890).await; + queue(&db, internal_id, 0).await; + + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the summaries"); + + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].chat_id, TelegramChatId::new(-1001234567890)); + assert_eq!(claimed[0].shrink_date, Utc::now().date_naive()); + assert_eq!(claimed[0].attempts, 0); +} + +/// The whole point of the lease: a summary being sent is invisible to everyone else, and +/// nothing here holds a lock long enough to do that on its own. +#[tokio::test] +async fn a_claimed_summary_is_not_claimed_again() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + queue(&db, create_chat(&db, -1001234567890).await, 0).await; + + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert_eq!(claimed.len(), 1); + let claimed_again = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert!(claimed_again.is_empty()); +} + +/// A worker that dies mid-batch must not take its summaries down with it — which is the whole +/// reason the queue exists. +#[tokio::test] +async fn a_summary_of_an_expired_lease_comes_back() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + queue(&db, create_chat(&db, -1001234567890).await, 0).await; + + let expired = Utc::now() - Duration::from_secs(1); + let claimed = repo.claim_due(Limit::new(10), expired) + .await.expect("couldn't claim the summaries"); + assert_eq!(claimed.len(), 1); + let claimed_again = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert_eq!(claimed_again.len(), 1); + assert_eq!(claimed_again[0].id, claimed[0].id); +} + +/// Two runs of the same day owe the chat one message, not two. The unique index is what says so. +#[tokio::test] +async fn the_same_chat_and_day_is_queued_once() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + let internal_id = create_chat(&db, -1001234567890).await; + + queue(&db, internal_id, 0).await; + queue(&db, internal_id, 0).await; + + let pending = repo.count_pending() + .await.expect("couldn't count the pending summaries"); + assert_eq!(pending, 1); +} + +/// Yesterday's summary and today's are different messages, so both are owed. +#[tokio::test] +async fn each_day_is_queued_on_its_own() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + let internal_id = create_chat(&db, -1001234567890).await; + + queue(&db, internal_id, 0).await; + queue(&db, internal_id, 1).await; + + let pending = repo.count_pending().await.expect("couldn't count the pending summaries"); + assert_eq!(pending, 2); +} + +#[tokio::test] +async fn a_postponed_summary_counts_its_attempts() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + queue(&db, create_chat(&db, -1001234567890).await, 0).await; + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + + let attempts = repo.postpone(claimed[0].id, Utc::now() - Duration::from_secs(1)) + .await.expect("couldn't postpone the summary"); + assert_eq!(attempts, 1); + + // The count the back-off is computed from has to survive the round trip, or every attempt + // would rest as long as the first. + let claimed_again = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert_eq!(claimed_again.len(), 1); + assert_eq!(claimed_again[0].attempts, 1); +} + +/// A finished row stays in the table as the account of what happened, but is out of the +/// worker's way and out of the gauge that says how much work is left. +#[tokio::test] +async fn a_finished_summary_is_kept_but_never_claimed() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + queue(&db, create_chat(&db, -1001234567890).await, 0).await; + queue(&db, create_chat(&db, -1009876543210).await, 0).await; + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert_eq!(claimed.len(), 2); + + repo.finish(claimed[0].id, BroadcastState::Sent) + .await.expect("couldn't finish the summary"); + repo.finish(claimed[1].id, BroadcastState::Unreachable) + .await.expect("couldn't finish the summary"); + + let claimed_again = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert!(claimed_again.is_empty()); + let pending = repo.count_pending() + .await.expect("couldn't count the pending summaries"); + assert_eq!(pending, 0); + + assert_eq!(finished_states(&db).await, + vec![("sent".to_owned(), 1), ("unreachable".to_owned(), 1)]); +} + +/// Every terminal state has to survive the trip to the database and back, or a row would end up +/// counted under the wrong ending. +#[tokio::test] +async fn every_terminal_state_survives_the_round_trip() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + for (i, _) in BroadcastState::TERMINAL.iter().enumerate() { + let telegram_id = -1001234567890 - i64::try_from(i).expect("the index fits"); + queue(&db, create_chat(&db, telegram_id).await, 0).await; + } + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + + for (broadcast, state) in claimed.iter().zip(BroadcastState::TERMINAL) { + repo.finish(broadcast.id, state) + .await.expect("couldn't finish the summary"); + } + + let finished = finished_states(&db).await; + for state in BroadcastState::TERMINAL { + assert!(finished.contains(&(state.to_string(), 1)), "{state} is missing from {finished:?}"); + } +} + +#[tokio::test] +async fn only_the_finished_rows_are_cleaned_up() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + queue(&db, create_chat(&db, -1001234567890).await, 0).await; + queue(&db, create_chat(&db, -1009876543210).await, 0).await; + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + repo.finish(claimed[0].id, BroadcastState::Sent) + .await.expect("couldn't finish the summary"); + + // Nothing has been finished for long enough yet. + let removed = repo.delete_finished(Utc::now() - Duration::from_secs(600)) + .await.expect("couldn't clean the summaries up"); + assert_eq!(removed, 0); + + let removed = repo.delete_finished(Utc::now() + Duration::from_secs(600)) + .await.expect("couldn't clean the summaries up"); + assert_eq!(removed, 1); + let pending = repo.count_pending() + .await.expect("couldn't count the pending summaries"); + assert_eq!(pending, 1); +} + +/// A chat known only by its `chat_instance` can never be messaged, so a row pointing at one is +/// given up on rather than handed to the worker — and must not come back with every tick. +#[tokio::test] +async fn a_summary_for_a_chat_without_a_telegram_id_is_given_up_on() { + let db = fresh_db().await; + let repo = ScheduledBroadcasts::new(db.clone()); + let internal_id = sqlx::query_scalar!("INSERT INTO Chats (chat_instance) VALUES ('inline-only') RETURNING id") + .fetch_one(&db).await.expect("couldn't create the inline-only chat"); + queue(&db, internal_id, 0).await; + + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the summaries"); + assert!(claimed.is_empty()); + + assert_eq!(finished_states(&db).await, vec![("failed".to_owned(), 1)]); + let claimed_again = repo.claim_due(Limit::new(10), Utc::now()) + .await.expect("couldn't claim the summaries"); + assert!(claimed_again.is_empty()); +} diff --git a/src/repo/test/chats.rs b/src/repo/test/chats.rs index 46dc395..1176f10 100644 --- a/src/repo/test/chats.rs +++ b/src/repo/test/chats.rs @@ -5,7 +5,7 @@ use crate::domain::primitives::chat::{InternalChatId, TelegramChatId, TelegramCh use crate::domain::primitives::chat::{ChatIdFull, ChatIdKind, ChatIdPartiality, ChatIdSource}; use crate::repo; use crate::repo::ChatMigrationOutcome; -use crate::repo::test::{CHAT_ID, fresh_db, UID, USER_ID}; +use crate::repo::test::{fresh_db, repos, CHAT_ID, UID, USER_ID}; use crate::repo::test::dicks::create_user; #[tokio::test] @@ -385,8 +385,7 @@ async fn migrate_chat_id() { let db = fresh_db().await; create_user(&db).await; - let chats = repo::Chats::new(db.clone(), Default::default()); - let dicks = repo::Dicks::new(db.clone(), Default::default()); + let repo::Repositories { chats, dicks, .. } = repos(&db); let (old, new) = (TelegramChatId::new(CHAT_ID), TelegramChatId::new(-1001234567890)); // nothing is known about the group yet — the migration is a no-op rather than an error, and diff --git a/src/repo/test/deletions.rs b/src/repo/test/deletions.rs new file mode 100644 index 0000000..6404a12 --- /dev/null +++ b/src/repo/test/deletions.rs @@ -0,0 +1,285 @@ +use std::time::Duration; +use domain_types::traits::SaturatingInto; +use chrono::Utc; +use crate::config::MessageGroup; +use crate::domain::primitives::{Count, LanguageCode, Limit}; +use crate::domain::primitives::chat::{InlineMessageId, TelegramChatId, TelegramMessageId}; +use crate::repo::{DeletionState, DeletionTarget, MessageKind, NewDeletion, ScheduledDeletion, ScheduledDeletions}; +use crate::repo::test::{far_future, fresh_db}; + +const CHAT_ID: i64 = -1001234567890; + +fn chat_message(message_id: u32) -> DeletionTarget { + DeletionTarget::ChatMessage { + chat_id: TelegramChatId::new(CHAT_ID), + message_id: TelegramMessageId::new(message_id), + } +} + +fn due(target: DeletionTarget, kind: MessageKind) -> NewDeletion { + NewDeletion { + target, + kind, + group: MessageGroup::Notice, + lang_code: LanguageCode::new("en".to_owned()), + fire_after: Utc::now() - Duration::from_secs(1), + } +} + +#[tokio::test] +async fn only_the_due_messages_are_claimed() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + + let later = NewDeletion { fire_after: Utc::now() + Duration::from_secs(600), ..due(chat_message(2), MessageKind::Reply) }; + repo.schedule(&[due(chat_message(1), MessageKind::Reply), later]) + .await.expect("couldn't schedule the deletions"); + + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].target, chat_message(1)); + assert_eq!(claimed[0].kind, MessageKind::Reply); + assert_eq!(claimed[0].state, DeletionState::Created); + + let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 2); +} + +/// The whole point of the lease: a message being worked on is invisible to everyone else, and +/// nothing here holds a lock long enough to do that on its own. +#[tokio::test] +async fn a_claimed_message_is_not_claimed_again() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed.len(), 1); + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert!(claimed_again.is_empty()); +} + +/// A worker that dies mid-batch must not take its messages down with it. +#[tokio::test] +async fn a_message_of_an_expired_lease_comes_back() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + + let expired = Utc::now() - Duration::from_secs(1); + let claimed = repo.claim_due(Limit::new(10), expired).await.expect("couldn't claim the deletions"); + assert_eq!(claimed.len(), 1); + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed_again.len(), 1); + assert_eq!(claimed_again[0].id, claimed[0].id); +} + +#[tokio::test] +async fn an_inline_message_survives_the_round_trip() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + let target = DeletionTarget::InlineMessage(InlineMessageId::new("AgAAAOEcAABzXwsRJ0Cs2A".to_owned())); + + repo.schedule(&[due(target.clone(), MessageKind::Inline)]) + .await.expect("couldn't schedule the deletion"); + + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].target, target); + assert_eq!(claimed[0].kind, MessageKind::Inline); +} + +#[tokio::test] +async fn the_same_message_is_scheduled_once() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion again"); + + let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 1); +} + +#[tokio::test] +async fn a_warned_message_comes_back_at_the_end_of_the_grace_period() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + + repo.mark_warned(claimed[0].id, Utc::now() + Duration::from_secs(600)) + .await.expect("couldn't mark the deletion as warned"); + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert!(claimed_again.is_empty()); + + repo.mark_warned(claimed[0].id, Utc::now() - Duration::from_secs(1)) + .await.expect("couldn't mark the deletion as warned"); + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed_again.len(), 1); + assert_eq!(claimed_again[0].state, DeletionState::Warned); +} + +#[tokio::test] +async fn a_postponed_message_counts_its_attempts() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + let claimed = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + + let attempts = repo.postpone(claimed[0].id, Utc::now() - Duration::from_secs(1)) + .await.expect("couldn't postpone the deletion"); + assert_eq!(attempts, 1); + let attempts = repo.postpone(claimed[0].id, Utc::now() - Duration::from_secs(1)) + .await.expect("couldn't postpone the deletion again"); + assert_eq!(attempts, 2); + + // The count the back-off is computed from has to survive the round trip, or every attempt + // would rest as long as the first. + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert_eq!(claimed_again.len(), 1); + assert_eq!(claimed_again[0].attempts, 2); +} + +/// A finished row stays in the table as the account of what happened, but is out of the +/// worker's way and out of the gauge that says how much work is left. +#[tokio::test] +async fn a_finished_message_is_kept_but_never_claimed() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(chat_message(2), MessageKind::Command)]) + .await.expect("couldn't schedule the deletions"); + let claimed = repo.claim_due(Limit::new(10), Utc::now() - Duration::from_secs(1)) + .await.expect("couldn't claim the deletions"); + assert_eq!(claimed.len(), 2); + + repo.finish(claimed[0].id, DeletionState::Removed).await.expect("couldn't finish the deletion"); + repo.finish(claimed[1].id, DeletionState::Failed).await.expect("couldn't fail the deletion"); + + let claimed_again = repo.claim_due(Limit::new(10), far_future()).await.expect("couldn't claim the deletions"); + assert!(claimed_again.is_empty()); + let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 0); + + let mut finished = repo.count_finished().await.expect("couldn't count the finished deletions"); + finished.sort_by_key(|(state, _)| state.to_string()); + assert_eq!(finished, vec![(DeletionState::Failed, Count::::new(1)), (DeletionState::Removed, Count::::new(1))]); +} + +/// Every terminal state has to survive the trip to the database and back, or a row would end up +/// counted under the wrong ending — the two-word one especially, as it is the only place the +/// snake_case spelling of the enum matters. +#[tokio::test] +async fn every_terminal_state_survives_the_round_trip() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + let messages: Vec<_> = (1..=DeletionState::TERMINAL.len()) + .map(|i| due(chat_message(i.saturating_into()), MessageKind::Reply)) + .collect(); + repo.schedule(&messages).await.expect("couldn't schedule the deletions"); + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the deletions"); + + for (deletion, state) in claimed.iter().zip(DeletionState::TERMINAL) { + repo.finish(deletion.id, state).await.expect("couldn't finish the deletion"); + } + + let finished = repo.count_finished().await.expect("couldn't count the finished deletions"); + for state in DeletionState::TERMINAL { + assert!(finished.contains(&(state, Count::::new(1))), "{state} is missing from {finished:?}"); + } +} + +#[tokio::test] +async fn only_the_finished_rows_are_cleaned_up() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(chat_message(2), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletions"); + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the deletions"); + repo.finish(claimed[0].id, DeletionState::Failed) + .await.expect("couldn't fail the deletion"); + + // Nothing has been finished for long enough yet. + let removed = repo.delete_finished(Utc::now() - Duration::from_secs(600)) + .await.expect("couldn't clean the deletions up"); + assert_eq!(removed, 0); + + let removed = repo.delete_finished(Utc::now() + Duration::from_secs(600)) + .await.expect("couldn't clean the deletions up"); + assert_eq!(removed, 1); + let pending = repo.count_pending() + .await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 1); +} + +/// A row addressing no message can only be made by hand, around the CHECK constraint that +/// forbids it. It must not be handed to the worker as some empty id it would then spend three +/// attempts on — and it must not keep coming back with every tick either. +#[tokio::test] +async fn a_row_that_addresses_no_message_is_given_up_on() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db.clone()); + sqlx::query!("ALTER TABLE Scheduled_Message_Deletions DROP CONSTRAINT scheduled_message_deletions_check") + .execute(&db).await.expect("couldn't drop the check constraint"); + sqlx::query!("INSERT INTO Scheduled_Message_Deletions (message_kind, message_group, lang_code, fire_after) + VALUES ('reply', 'notice', 'en', current_timestamp - interval '1 minute')") + .execute(&db).await.expect("couldn't insert the malformed row"); + + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the deletions"); + assert!(claimed.is_empty()); + + let finished = repo.count_finished() + .await.expect("couldn't count the finished deletions"); + assert_eq!(finished, vec![(DeletionState::Failed, Count::::new(1))]); + let claimed_again = repo.claim_due(Limit::new(10), Utc::now()) + .await.expect("couldn't claim the deletions"); + assert!(claimed_again.is_empty()); +} + +/// A removed message is history like any other ending, so its row waits for the cleaning +/// process rather than disappearing with it. +#[tokio::test] +async fn a_removed_message_stays_until_it_is_cleaned_up() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + repo.schedule(&[due(chat_message(1), MessageKind::Reply)]) + .await.expect("couldn't schedule the deletion"); + let claimed = repo.claim_due(Limit::new(10), far_future()) + .await.expect("couldn't claim the deletions"); + + repo.finish(claimed[0].id, DeletionState::Removed) + .await.expect("couldn't finish the deletion"); + + let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 0); + let finished = repo.count_finished().await.expect("couldn't count the finished deletions"); + assert_eq!(finished, vec![(DeletionState::Removed, Count::::new(1))]); + + let removed = repo.delete_finished(Utc::now() + Duration::from_secs(600)) + .await.expect("couldn't clean the deletions up"); + assert_eq!(removed, 1); +} + +#[tokio::test] +async fn a_cancelled_message_is_kept() { + let db = fresh_db().await; + let repo = ScheduledDeletions::new(db); + let inline = DeletionTarget::InlineMessage(InlineMessageId::new("AgAAAOEcAABzXwsRJ0Cs2A".to_owned())); + repo.schedule(&[due(chat_message(1), MessageKind::Reply), due(inline.clone(), MessageKind::Inline)]) + .await.expect("couldn't schedule the deletions"); + + repo.cancel(&chat_message(1)).await.expect("couldn't cancel the deletion"); + repo.cancel(&inline).await.expect("couldn't cancel the deletion"); + + let pending = repo.count_pending().await.expect("couldn't count the pending deletions"); + assert_eq!(pending, 0); +} diff --git a/src/repo/test/dicks.rs b/src/repo/test/dicks.rs index 0fe8b53..dca551c 100644 --- a/src/repo/test/dicks.rs +++ b/src/repo/test/dicks.rs @@ -4,7 +4,7 @@ use crate::config::FeatureToggles; use crate::domain::primitives::{Bet, DaysCount, Length, LengthChange, Limit, Offset, Position}; use crate::domain::primitives::chat::{ChatIdKind, ChatIdPartiality}; use crate::repo; -use crate::repo::test::{user_id, CHAT_ID, CHAT_ID_KIND, get_chat_id_and_dicks, NAME, fresh_db, UID, USER_ID}; +use crate::repo::test::{fresh_db, get_chat_id_and_dicks, internal_chat_id, repos, seed_aged_dick, user_id, CHAT_ID_KIND, NAME, UID, USER_ID}; const INACTIVITY_DAYS: DaysCount = DaysCount::new(7); @@ -12,26 +12,6 @@ fn increment_of(value: i64) -> LengthChange { LengthChange::signed(value) } -async fn internal_chat_id(db: &Pool) -> i64 { - sqlx::query_scalar!("SELECT id FROM Chats WHERE chat_id = $1", CHAT_ID) - .fetch_one(db) - .await - .expect("couldn't resolve the internal chat id") -} - -/// Inserts a `Dicks` row directly (bypassing `create_or_grow`, whose trigger always stamps -/// `updated_at = now`), so we can seed a dick that looks like it decayed to `0` a while ago — -/// mirrors `seed_aged_dick` in `repo/test/shrinks.rs`. -async fn seed_stale_zero_length_dick(db: &Pool, internal_chat_id: i64, uid: i64, days_ago: i32) { - sqlx::query!( - "INSERT INTO Dicks (uid, chat_id, length, updated_at) \ - VALUES ($1, $2, 0, current_timestamp - make_interval(days => $3))", - uid, internal_chat_id, days_ago) - .execute(db) - .await - .expect("couldn't seed a stale zero-length dick"); -} - #[tokio::test] async fn test_all() { let db = fresh_db().await; @@ -143,7 +123,7 @@ async fn test_hide_inactive_zero_length_from_top() { let stale_uid = UID + 1; users.create_or_update(user_id(stale_uid), "stale-zero") .await.expect("couldn't create the stale user"); - seed_stale_zero_length_dick(&db, internal_chat_id, stale_uid, 10).await; + seed_aged_dick(&db, internal_chat_id, stale_uid, 0, 10).await; // A fresh, zero-length dick (just created today) — must stay visible despite length = 0. let fresh_uid = UID + 2; @@ -184,7 +164,7 @@ async fn test_hide_inactive_zero_length_from_top_disabled() { let stale_uid = UID + 1; users.create_or_update(user_id(stale_uid), "stale-zero") .await.expect("couldn't create the stale user"); - seed_stale_zero_length_dick(&db, internal_chat_id, stale_uid, 10).await; + seed_aged_dick(&db, internal_chat_id, stale_uid, 0, 10).await; let top = dicks.get_top(&chat_id, Offset::new(0), Limit::new(10), INACTIVITY_DAYS) .await.expect("couldn't fetch the top"); @@ -252,8 +232,7 @@ pub async fn create_another_user_and_dick( assert!(n > 1); let n = n.to_i64().expect("couldn't convert n to i64"); - let users = repo::Users::new(db.clone()); - let dicks = repo::Dicks::new(db.clone(), Default::default()); + let repo::Repositories { users, dicks, .. } = repos(db); let uid2 = user_id(UID + n - 1); users.create_or_update(uid2, name) .await.unwrap_or_else(|_| panic!("couldn't create a user #{n}")); diff --git a/src/repo/test/import.rs b/src/repo/test/import.rs index f773b86..aaef4df 100644 --- a/src/repo/test/import.rs +++ b/src/repo/test/import.rs @@ -4,7 +4,7 @@ use crate::domain::objects::ExternalUser; use crate::domain::primitives::{Length, LengthChange, UserId}; use crate::domain::primitives::chat::{ChatIdKind, TelegramChatId}; use crate::repo; -use crate::repo::test::{user_id, CHAT_ID, CHAT_ID_KIND, fresh_db, UID, USER_ID}; +use crate::repo::test::{fresh_db, repos, user_id, CHAT_ID, CHAT_ID_KIND, UID, USER_ID}; use crate::repo::test::dicks::{check_dick, create_dick, create_user, create_user_and_dick_2}; /// A chat the import is not asked about, used to check it stays untouched. @@ -46,8 +46,7 @@ mod import_semantics { #[tokio::test] async fn every_dick_grows_by_its_own_length() { let db = fresh_db().await; - let import = repo::Import::new(db.clone()); - let dicks = repo::Dicks::new(db.clone(), Default::default()); + let repo::Repositories { import, dicks, .. } = repos(&db); let uid2 = user_id(UID + 1); create_user(&db).await; diff --git a/src/repo/test/loans.rs b/src/repo/test/loans.rs index 0284f54..1a76192 100644 --- a/src/repo/test/loans.rs +++ b/src/repo/test/loans.rs @@ -4,7 +4,7 @@ use crate::{config, repo}; use crate::domain::primitives::{Debt, LoanPayout, PayoutRatio}; use crate::repo::BorrowResult; use crate::repo::test::dicks::{create_dick, create_user}; -use crate::repo::test::{user_id, CHAT_ID, NAME, fresh_db, UID, USER_ID, CHAT_ID_KIND}; +use crate::repo::test::{fresh_db, user_id, CHAT_ID, CHAT_ID_KIND, NAME, UID, USER_ID}; use domain_types::literal; #[tokio::test] diff --git a/src/repo/test/mod.rs b/src/repo/test/mod.rs index 846ef70..6463be0 100644 --- a/src/repo/test/mod.rs +++ b/src/repo/test/mod.rs @@ -9,10 +9,13 @@ mod stats; mod shrinks; mod announcements; mod bans; +mod broadcasts; +mod deletions; use std::str::FromStr; use std::sync::atomic::{AtomicU32, Ordering}; use std::time::Duration; +use chrono::{DateTime, Utc}; use tokio::sync::OnceCell; use reqwest::Url; use domain_types::traits::SaturatingInto; @@ -80,6 +83,51 @@ pub fn get_chat_id_and_dicks(db: &Pool) -> (ChatIdKind, repo::Dicks) { (chat_id, dicks) } +/// Every repository over the same database, built the way `main` builds them. +/// +/// Meant to be destructured, so a test names the repositories it wants and no more: +/// `let repo::Repositories { users, dicks, .. } = repos(&db);`. A test that needs a repository +/// configured differently — a feature toggle turned on — still builds that one itself. +pub fn repos(db: &Pool) -> repo::Repositories { + repo::Repositories::new(db, &Default::default()) +} + +/// The `Chats.id` of [`CHAT_ID`], which is what every other table's `chat_id` column points at. +pub async fn internal_chat_id(db: &Pool) -> i64 { + sqlx::query_scalar!("SELECT id FROM Chats WHERE chat_id = $1", CHAT_ID) + .fetch_one(db) + .await + .expect("couldn't resolve the internal chat id") +} + +/// A chat with nothing but a Telegram id, for the tests that need a second one or a chat without +/// any of the rows `create_or_grow` would bring with it. +pub async fn create_chat(db: &Pool, telegram_id: i64) -> i64 { + sqlx::query_scalar!("INSERT INTO Chats (chat_id) VALUES ($1) RETURNING id", telegram_id) + .fetch_one(db) + .await + .expect("couldn't create the chat") +} + +/// A dick inserted directly, with a length and an age of the test's choosing. +/// +/// A direct `INSERT` is the only way: the `Dicks` BEFORE UPDATE trigger forbids touching a row that +/// was grown today, which a freshly created dick always is. +pub async fn seed_aged_dick(db: &Pool, internal_chat_id: i64, uid: i64, length: i64, days_ago: i32) { + sqlx::query!( + "INSERT INTO Dicks (uid, chat_id, length, updated_at) \ + VALUES ($1, $2, $3, current_timestamp - make_interval(days => $4))", + uid, internal_chat_id, length, days_ago) + .execute(db) + .await + .expect("couldn't seed an aged dick"); +} + +/// A lease, or any other deadline, far enough out that nothing under test can outlive it. +pub fn far_future() -> DateTime { + Utc::now() + Duration::from_secs(600) +} + /// One Postgres for the whole binary, reused across runs, with a database per test. struct SharedPostgres { port: u16, diff --git a/src/repo/test/pvpstats.rs b/src/repo/test/pvpstats.rs index 2f68f5e..68d3c28 100644 --- a/src/repo/test/pvpstats.rs +++ b/src/repo/test/pvpstats.rs @@ -3,7 +3,7 @@ use crate::domain::primitives::Bet; use crate::domain::primitives::chat::ChatIdPartiality; use crate::repo; use crate::repo::test::dicks::{create_dick, create_user, create_user_and_dick_2}; -use crate::repo::test::{user_id, fresh_db, CHAT_ID_KIND, UID, USER_ID}; +use crate::repo::test::{fresh_db, user_id, CHAT_ID_KIND, UID, USER_ID}; #[tokio::test] async fn test_all() { diff --git a/src/repo/test/shrinks.rs b/src/repo/test/shrinks.rs index d76245a..434093c 100644 --- a/src/repo/test/shrinks.rs +++ b/src/repo/test/shrinks.rs @@ -1,29 +1,19 @@ use sqlx::{Pool, Postgres}; -use crate::domain::primitives::{DaysCount, LengthChange, Limit, Offset, Ratio, Username}; -use crate::domain::primitives::chat::TelegramChatId; +use crate::domain::primitives::{DaysCount, LengthChange, Limit, Offset, Ratio}; +use crate::domain::primitives::chat::{InternalChatId, TelegramChatId}; use crate::repo; -use crate::repo::test::{user_id, CHAT_ID, CHAT_ID_KIND, NAME, fresh_db, UID, USER_ID}; +use crate::repo::test::{fresh_db, internal_chat_id, repos, seed_aged_dick, user_id, CHAT_ID, CHAT_ID_KIND, NAME, UID, USER_ID}; use domain_types::literal; const GRACE_DAYS: DaysCount = DaysCount::new(7); +/// Small, so every test here crosses a batch boundary instead of fitting into one batch. +const BATCH_SIZE: Limit = Limit::new(2); + /// `<= 1` disables the ramp, applying the full ratio from the first overdue day — the old, /// pre-ramp behavior that most tests want so their expected losses stay simple round numbers. const NO_RAMP: DaysCount = DaysCount::new(0); -/// Inserts a dick directly (bypassing `create_or_grow`) with an explicit age, so we can seed -/// dicks that look stale. A direct INSERT is required because the `Dicks` BEFORE UPDATE trigger -/// forbids touching a row that was grown today — which a freshly created dick always is. -async fn seed_aged_dick(db: &Pool, internal_chat_id: i64, uid: i64, length: i64, days_ago: i32) { - sqlx::query!( - "INSERT INTO Dicks (uid, chat_id, length, updated_at) \ - VALUES ($1, $2, $3, current_timestamp - make_interval(days => $4))", - uid, internal_chat_id, length, days_ago) - .execute(db) - .await - .expect("couldn't seed an aged dick"); -} - async fn seed_aged_dick_with_bonus_attempts( db: &Pool, internal_chat_id: i64, @@ -65,13 +55,6 @@ async fn seed_old_shrink(db: &Pool, internal_chat_id: i64, uid: i64, l .expect("couldn't seed an old shrink"); } -async fn internal_chat_id(db: &Pool) -> i64 { - sqlx::query_scalar!("SELECT id FROM Chats WHERE chat_id = $1", CHAT_ID) - .fetch_one(db) - .await - .expect("couldn't resolve the internal chat id") -} - async fn updated_at_of(db: &Pool, uid: i64, internal_chat_id: i64) -> chrono::DateTime { sqlx::query_scalar!("SELECT updated_at FROM Dicks WHERE uid = $1 AND chat_id = $2", uid, internal_chat_id) .fetch_one(db) @@ -86,12 +69,51 @@ async fn length_of(db: &Pool, uid: i64, internal_chat_id: i64) -> i64 .expect("couldn't read length") } +/// What today's run took off that dick. The shrink no longer hands the events back, so this is +/// where a loss is read from — the same table the summary is rendered out of. +async fn lost_length_of(db: &Pool, uid: i64) -> i64 { + sqlx::query_scalar!( + "SELECT lost_length FROM Stale_Dick_Shrinks WHERE uid = $1 AND created_at = current_date", uid) + .fetch_one(db) + .await + .expect("couldn't read the logged loss") +} + +/// The summaries queued for today, as `(internal chat id, state)`. +async fn queued_broadcasts(db: &Pool) -> Vec<(i64, String)> { + sqlx::query!( + r#"SELECT chat_id, state::text AS "state!" FROM Scheduled_Shrink_Broadcasts + WHERE shrink_date = current_date ORDER BY chat_id"#) + .fetch_all(db) + .await + .expect("couldn't read the queued summaries") + .into_iter() + .map(|row| (row.chat_id, row.state)) + .collect() +} + +/// Every chat, walked one batch at a time — what the run does, with a batch size small enough that +/// these tests cross a batch boundary rather than fitting into one. +async fn shrink_all(shrinks: &repo::Shrinks, ratio: Ratio, grace_days: DaysCount, ramp_up_days: DaysCount) + -> repo::ShrinkBatchOutcome +{ + let mut total = repo::ShrinkBatchOutcome::default(); + let mut after = None; + loop { + let batch = shrinks.select_chats_batch(after, BATCH_SIZE) + .await.expect("couldn't read a batch of chats"); + let Some(last) = batch.last().copied() else { break }; + after = Some(last); + total += shrinks.perform_daily_shrink(&batch, ratio, grace_days, ramp_up_days) + .await.expect("couldn't perform the daily shrink"); + } + total +} + #[tokio::test] async fn test_perform_daily_shrink() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); // A fresh dick for USER_ID — also creates the Chats row. It must NOT be shrunk (grown today). users.create_or_update(USER_ID, NAME) @@ -120,17 +142,18 @@ async fn test_perform_daily_shrink() { .await.expect("couldn't create the bonus user"); seed_aged_dick_with_bonus_attempts(&db, chat_id, bonus_uid, 100, 10, 1).await; - let events = shrinks.perform_daily_shrink(literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP) - .await.expect("couldn't perform the daily shrink"); + let outcome = shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; - assert_eq!(events.len(), 2, "the two stale, positive dicks should have shrunk"); - let event = events.iter().find(|e| e.uid == user_id(victim_uid)) - .expect("the victim's shrink event is missing"); - assert_eq!(event.owner_name, Username::from("stale-victim")); - assert_eq!(event.lost_length, 10, "loss = ceil(100 * 0.1)"); - assert_eq!(event.new_length, 90); - assert_eq!(event.messageable_chat_id, Some(TelegramChatId::new(CHAT_ID))); - assert!(!event.is_unreachable, "the bot has no reason to think it can't post here"); + assert_eq!(outcome.victims, 2, "the two stale, positive dicks should have shrunk"); + assert_eq!(outcome.to_broadcast, 2); + assert_eq!(outcome.inline_only, 0); + assert_eq!(outcome.unreachable, 0); + assert_eq!(lost_length_of(&db, victim_uid).await, 10, "loss = ceil(100 * 0.1)"); + assert_eq!(length_of(&db, victim_uid, chat_id).await, 90); + + // One summary for the chat, however many of its dicks shrank. + assert_eq!(outcome.chats_queued, 1); + assert_eq!(queued_broadcasts(&db).await, vec![(chat_id, "created".to_owned())]); // The fresh and the zero-length dicks are untouched. assert_eq!(length_of(&db, UID, chat_id).await, 100, "the fresh dick must not shrink"); @@ -150,10 +173,7 @@ async fn test_perform_daily_shrink() { #[tokio::test] async fn test_perform_daily_shrink_reports_unreachable_chats() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); - let chats = repo::Chats::new(db.clone(), Default::default()); + let repo::Repositories { dicks, shrinks, users, chats, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the user"); @@ -169,24 +189,80 @@ async fn test_perform_daily_shrink_reports_unreachable_chats() { chats.mark_unreachable(&TelegramChatId::new(CHAT_ID)) .await.expect("couldn't mark the chat as unreachable"); - let events = shrinks.perform_daily_shrink(literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP) - .await.expect("couldn't perform the daily shrink"); + let outcome = shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; + + assert_eq!(outcome.victims, 1); + assert_eq!(outcome.unreachable, 1, "the chat is messageable in principle, just not right now"); + assert_eq!(outcome.to_broadcast, 0); + assert_eq!(outcome.chats_skipped, 1); + assert_eq!(length_of(&db, victim_uid, chat_id).await, 90, "an unreachable chat shrinks like any other"); + + // Nothing is queued for it, which is the point: the worker never spends a request on a chat + // the bot is already known to have lost. + assert_eq!(outcome.chats_queued, 0); + assert!(queued_broadcasts(&db).await.is_empty()); +} + +/// A chat known only by its `chat_instance` can't be messaged proactively at all, so it shrinks +/// without ever being queued. Its members still see the events through the `shrinks` command. +#[tokio::test] +async fn test_perform_daily_shrink_queues_nothing_for_an_inline_only_chat() { + let db = fresh_db().await; + let repo::Repositories { shrinks, users, .. } = repos(&db); + + let chat_id = sqlx::query_scalar!("INSERT INTO Chats (chat_instance) VALUES ('inline-only') RETURNING id") + .fetch_one(&db).await.expect("couldn't create the inline-only chat"); + + let victim_uid = UID + 1; + users.create_or_update(user_id(victim_uid), "stale-victim") + .await.expect("couldn't create the victim user"); + seed_aged_dick(&db, chat_id, victim_uid, 100, 10).await; + + let outcome = shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; + + assert_eq!(outcome.victims, 1); + assert_eq!(outcome.inline_only, 1); + assert_eq!(outcome.chats_queued, 0); + assert_eq!(length_of(&db, victim_uid, chat_id).await, 90); + assert!(queued_broadcasts(&db).await.is_empty()); +} + +/// The unique index is what keeps a chat from being told twice about the same day, however often +/// the run is repeated — the property that makes re-running a partly failed day safe. +#[tokio::test] +async fn test_perform_daily_shrink_queues_one_summary_per_chat_and_day() { + let db = fresh_db().await; + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); + + users.create_or_update(USER_ID, NAME) + .await.expect("couldn't create the primary user"); + dicks.create_or_grow(USER_ID, &CHAT_ID_KIND.into(), LengthChange::signed(100)) + .await.expect("couldn't create the fresh dick"); + let chat_id = internal_chat_id(&db).await; + + let victim_uid = UID + 1; + users.create_or_update(user_id(victim_uid), "stale-victim") + .await.expect("couldn't create the victim user"); + seed_aged_dick(&db, chat_id, victim_uid, 100, 10).await; + + let first = shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; + assert_eq!(first.chats_queued, 1); + + // The second run aborts on Stale_Dick_Shrinks' primary key, so nothing of it lands — neither a + // second length change nor a second summary. + let batch = shrinks.select_chats_batch(None, BATCH_SIZE) + .await.expect("couldn't read a batch of chats"); + let repeated = shrinks.perform_daily_shrink(&batch, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; + assert!(repeated.is_err(), "shrinking the same chat twice in one day must not go through"); - assert_eq!(events.len(), 1); - let event = &events[0]; - assert!(event.is_unreachable); - assert_eq!(event.messageable_chat_id, Some(TelegramChatId::new(CHAT_ID)), - "the chat is still messageable in principle — it just can't be reached right now"); - assert_eq!(event.new_length, 90, "an unreachable chat shrinks like any other"); assert_eq!(length_of(&db, victim_uid, chat_id).await, 90); + assert_eq!(queued_broadcasts(&db).await, vec![(chat_id, "created".to_owned())]); } #[tokio::test] async fn test_perform_daily_shrink_ramps_up_the_ratio() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user"); @@ -215,16 +291,11 @@ async fn test_perform_daily_shrink_ramps_up_the_ratio() { .await.expect("couldn't create the way-overdue user"); seed_aged_dick(&db, chat_id, way_overdue_uid, 1000, 20).await; - let events = shrinks.perform_daily_shrink(literal!(Ratio = 0.5), GRACE_DAYS, DaysCount::new(4)) - .await.expect("couldn't perform the daily shrink"); + shrink_all(&shrinks, literal!(Ratio = 0.5), GRACE_DAYS, DaysCount::new(4)).await; - let loss_of = |uid: i64| events.iter() - .find(|e| e.uid == user_id(uid)) - .unwrap_or_else(|| panic!("no shrink event for uid {uid}")) - .lost_length; - assert_eq!(loss_of(just_overdue_uid), 125, "1/4 of the ramp: ceil(1000 * 0.5 * 1/4)"); - assert_eq!(loss_of(fully_ramped_uid), 500, "ramp fully kicked in: ceil(1000 * 0.5)"); - assert_eq!(loss_of(way_overdue_uid), 500, "ramp is capped at the full ratio, not exceeded"); + assert_eq!(lost_length_of(&db, just_overdue_uid).await, 125, "1/4 of the ramp: ceil(1000 * 0.5 * 1/4)"); + assert_eq!(lost_length_of(&db, fully_ramped_uid).await, 500, "ramp fully kicked in: ceil(1000 * 0.5)"); + assert_eq!(lost_length_of(&db, way_overdue_uid).await, 500, "ramp is capped at the full ratio, not exceeded"); } /// The loss formula floors at `GREATEST(1, ...)`, so any neglected, positive-length dick loses at @@ -235,9 +306,7 @@ async fn test_perform_daily_shrink_ramps_up_the_ratio() { #[tokio::test] async fn test_perform_daily_shrink_floor_reaches_exactly_zero() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user"); @@ -251,13 +320,10 @@ async fn test_perform_daily_shrink_floor_reaches_exactly_zero() { seed_aged_dick(&db, chat_id, victim_uid, 1, 100).await; // ratio * length rounds down to 0 cm on its own — GREATEST(1, ...) must still floor it at 1. - let events = shrinks.perform_daily_shrink(literal!(Ratio = 0.01), GRACE_DAYS, NO_RAMP) - .await.expect("couldn't perform the daily shrink"); + shrink_all(&shrinks, literal!(Ratio = 0.01), GRACE_DAYS, NO_RAMP).await; - let event = events.iter().find(|e| e.uid == user_id(victim_uid)) - .expect("the 1cm dick must still shrink despite the tiny ratio"); - assert_eq!(event.lost_length, 1, "the floor must apply even though ratio * length rounds to 0"); - assert_eq!(event.new_length, 0); + assert_eq!(lost_length_of(&db, victim_uid).await, 1, + "the floor must apply even though ratio * length rounds to 0"); assert_eq!(length_of(&db, victim_uid, chat_id).await, 0); } @@ -272,9 +338,7 @@ async fn test_perform_daily_shrink_floor_reaches_exactly_zero() { #[tokio::test] async fn test_perform_daily_shrink_rejects_overflowing_grace_days_instead_of_wrapping() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user"); @@ -288,7 +352,8 @@ async fn test_perform_daily_shrink_rejects_overflowing_grace_days_instead_of_wra seed_aged_dick(&db, chat_id, victim_uid, 100, 100).await; let absurd_grace_days = DaysCount::new(3_000_000_000); // > i32::MAX (~2.15 billion), valid u32 - let result = shrinks.perform_daily_shrink(literal!(Ratio = 0.5), absurd_grace_days, NO_RAMP).await; + let chat_ids = &[InternalChatId::new(chat_id.try_into().expect("the internal chat id must be positive"))]; + let result = shrinks.perform_daily_shrink(chat_ids, literal!(Ratio = 0.5), absurd_grace_days, NO_RAMP).await; assert!(result.is_err(), "an out-of-range grace_days must error, not silently wrap to negative"); assert_eq!(length_of(&db, victim_uid, chat_id).await, 100, @@ -298,9 +363,7 @@ async fn test_perform_daily_shrink_rejects_overflowing_grace_days_instead_of_wra #[tokio::test] async fn test_get_shrinks_for_date_only_returns_that_day() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user"); @@ -314,8 +377,7 @@ async fn test_get_shrinks_for_date_only_returns_that_day() { seed_aged_dick(&db, chat_id, victim_uid, 100, 10).await; // Today's shrink (logged with created_at = current_date). - shrinks.perform_daily_shrink(literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP) - .await.expect("couldn't perform the daily shrink"); + shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; // An older shrink, on a different day — must not leak into today's exact-date query. seed_old_shrink(&db, chat_id, UID, 5, 8).await; @@ -333,9 +395,7 @@ async fn test_get_shrinks_for_date_only_returns_that_day() { #[tokio::test] async fn test_get_shrinks_for_date_pages() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user and the Chats row"); @@ -373,9 +433,7 @@ async fn test_get_shrinks_for_date_pages() { #[tokio::test] async fn test_get_latest_shrink_date_returns_none_without_history() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user and the Chats row"); @@ -393,9 +451,7 @@ async fn test_get_latest_shrink_date_returns_none_without_history() { #[tokio::test] async fn test_get_latest_and_adjacent_shrink_dates() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let shrinks = repo::Shrinks::new(db.clone()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, shrinks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user and the Chats row"); @@ -440,8 +496,7 @@ async fn test_get_latest_and_adjacent_shrink_dates() { #[tokio::test] async fn test_get_player_uids() { let db = fresh_db().await; - let dicks = repo::Dicks::new(db.clone(), Default::default()); - let users = repo::Users::new(db.clone()); + let repo::Repositories { dicks, users, .. } = repos(&db); users.create_or_update(USER_ID, NAME) .await.expect("couldn't create the primary user"); @@ -465,3 +520,40 @@ async fn test_get_player_uids() { user_id(UID + 2), ]); } + +/// The run walks the chats by their primary key, a batch at a time. An off-by-one in the keyset +/// would silently skip a chat every batch — nobody's dick would shrink there and no summary would +/// be owed — so this seeds more chats than fit in one batch and insists that every one of them was +/// reached. +#[tokio::test] +async fn every_chat_is_reached_across_the_batches() { + let db = fresh_db().await; + let repo::Repositories { shrinks, users, .. } = repos(&db); + + // Five chats against a batch of two: the last batch is a partial one, which is where an + // off-by-one usually hides. + let mut seeded = Vec::new(); + for i in 0..5i64 { + let chat_id = sqlx::query_scalar!("INSERT INTO Chats (chat_id) VALUES ($1) RETURNING id", -1000 - i) + .fetch_one(&db).await.expect("couldn't create the chat"); + let uid = UID + 100 + i; + users.create_or_update(user_id(uid), "stale-victim") + .await.expect("couldn't create the victim user"); + seed_aged_dick(&db, chat_id, uid, 100, 10).await; + seeded.push((chat_id, uid)); + } + + let outcome = shrink_all(&shrinks, literal!(Ratio = 0.1), GRACE_DAYS, NO_RAMP).await; + + assert_eq!(outcome.victims, 5, "every chat's dick must have shrunk"); + assert_eq!(outcome.chats_queued, 5, "every chat must be owed a summary"); + for (chat_id, uid) in &seeded { + assert_eq!(length_of(&db, *uid, *chat_id).await, 90, "the dick in chat {chat_id} was skipped"); + } + + let mut queued: Vec = queued_broadcasts(&db).await.into_iter().map(|(id, _)| id).collect(); + queued.sort_unstable(); + let mut expected: Vec = seeded.into_iter().map(|(chat_id, _)| chat_id).collect(); + expected.sort_unstable(); + assert_eq!(queued, expected); +} diff --git a/src/repo/test/stats.rs b/src/repo/test/stats.rs index 5de0b8b..d7810df 100644 --- a/src/repo/test/stats.rs +++ b/src/repo/test/stats.rs @@ -1,7 +1,7 @@ use crate::domain::primitives::LengthChange; use crate::domain::primitives::chat::{ChatIdKind, ChatIdPartiality, TelegramChatId}; use crate::repo; -use crate::repo::test::{CHAT_ID, fresh_db, USER_ID}; +use crate::repo::test::{fresh_db, repos, CHAT_ID, USER_ID}; use crate::repo::test::dicks::create_user; fn increment_of(value: i64) -> LengthChange { @@ -11,8 +11,7 @@ fn increment_of(value: i64) -> LengthChange { #[tokio::test] async fn test_all() { let db = fresh_db().await; - let personal_stats = repo::PersonalStatsRepo::new(db.clone()); - let dicks = repo::Dicks::new(db.clone(), Default::default()); + let repo::Repositories { personal_stats, dicks, .. } = repos(&db); let chat_id_1 = ChatIdKind::ID(TelegramChatId::new(CHAT_ID)); let chat_id_2 = ChatIdKind::ID(TelegramChatId::new(CHAT_ID + 1)); diff --git a/src/repo/test/users.rs b/src/repo/test/users.rs index 3c17656..430fa1b 100644 --- a/src/repo/test/users.rs +++ b/src/repo/test/users.rs @@ -3,7 +3,7 @@ use crate::domain::objects::User; use crate::domain::primitives::{DaysCount, LengthChange, Ratio, UserId}; use crate::domain::primitives::chat::{ChatIdKind, ChatIdPartiality, TelegramChatId}; use crate::repo; -use crate::repo::test::{user_id, CHAT_ID, NAME, fresh_db, UID, USER_ID}; +use crate::repo::test::{fresh_db, repos, user_id, CHAT_ID, NAME, UID, USER_ID}; use crate::repo::test::dicks::{create_another_user_and_dick, create_user_and_dick_2}; const INACTIVITY_DAYS: DaysCount = DaysCount::new(7); @@ -185,8 +185,7 @@ fn check_member_with_name(members: &[User], name: &str) { } async fn create_member(db: &Pool) { - let users = repo::Users::new(db.clone()); - let dicks = repo::Dicks::new(db.clone(), Default::default()); + let repo::Repositories { users, dicks, .. } = repos(db); let chat_id = ChatIdKind::ID(TelegramChatId::new(CHAT_ID)); let uid = USER_ID; diff --git a/src/scheduler/broadcasts.rs b/src/scheduler/broadcasts.rs new file mode 100644 index 0000000..aa53784 --- /dev/null +++ b/src/scheduler/broadcasts.rs @@ -0,0 +1,341 @@ +use std::time::Duration; +use autometrics::autometrics; +use chrono::Utc; +use futures::{stream, StreamExt}; +use teloxide::{ApiError, Bot, RequestError}; +use teloxide::adaptors::Throttle; +use teloxide::payloads::SendMessageSetters; +use teloxide::requests::Requester; +use teloxide::sugar::request::RequestLinkPreviewExt; +use teloxide::types::{ChatId, ReplyMarkup, UserId as TeloxideUserId}; +use teloxide::types::ParseMode::Html; +use domain_types::traits::ApproxInto; +use crate::config::AppConfig; +use crate::domain::primitives::{LanguageCode, Page, ScheduledBroadcastId, SupportedLanguage}; +use crate::domain::primitives::chat::ChatIdKind; +use crate::handlers::shrink::{build_shrink_keyboard, shrinks_page_impl, ShrinkView}; +use crate::metrics; +use crate::repo::{BroadcastState, Repositories, ScheduledBroadcast}; +use super::backoff; +use crate::topics::TopicPolicy; +use crate::users::LanguageService; + +/// The services every summary needs, bundled so the per-chat calls stay readable. +#[derive(Clone, Copy)] +pub struct BroadcastDeps<'a> { + pub bot: &'a Throttle, + pub repos: &'a Repositories, + pub language_service: &'a LanguageService, + pub topics: &'a TopicPolicy, + pub config: &'a AppConfig, +} + +/// What the worker decided to do with a row once it had tried to send its summary. +#[derive(Debug, PartialEq, Eq)] +enum Outcome { + /// The chat got its summary. + Sent, + /// Something transient went wrong; the row is tried again later. + Retry, + /// The summary sat in the queue until it stopped being worth sending. + Expired, + /// The bot can't post to that chat at all, which marks the chat too. + Unreachable, + /// It won't work, now or later, for a reason that says nothing about the chat. + Failed, +} + +/// Takes one batch of summaries whose time has come and sends each of them. +#[autometrics] +#[tracing::instrument(skip_all)] +pub async fn run_pending_broadcasts(deps: BroadcastDeps<'_>) -> anyhow::Result<()> { + let config = &deps.config.daily_shrink.broadcast; + let due = deps.repos.broadcasts + .claim_due(config.batch_size, Utc::now() + config.lease) + .await?; + // The empty runs are measured too: an idle worker is what tells a queue that keeps up from one + // that is merely being asked for less than it holds. + metrics::DAILY_SHRINK_BROADCAST_BATCH_SIZE.observe(due.len().approx_into()); + if due.is_empty() { + return Ok(()) + } + tracing::debug!(count = due.len(), "sending the shrink summaries that are due"); + + // Concurrently, because what one run gets through would otherwise be one chat per round trip to + // Telegram however large the batch — which is what let a broadcast to two hundred thousand + // chats outlast the day it belonged to. The rate is still Telegram's to set: every request here + // goes through the shared `Throttle`. + stream::iter(due) + .for_each_concurrent(usize::from(config.concurrency), |broadcast| async move { + send_and_record(deps, broadcast).await + }) + .await; + Ok(()) +} + +/// Removes the rows that were finished long enough ago. +/// +/// Separate from the worker on purpose: the finished rows are the only account of what the worker +/// did, so how long they are kept is a decision of its own, and clearing them must never be part of +/// the run that produced them. +#[autometrics] +#[tracing::instrument(skip_all)] +pub async fn clean_finished_broadcasts(repos: &Repositories, retention: Duration) -> anyhow::Result<()> { + let older_than = Utc::now() - retention; + tracing::debug!(%older_than, ?retention, "cleaning the finished shrink summaries up"); + let removed = repos.broadcasts.delete_finished(older_than).await?; + if removed > 0 { + tracing::info!(removed, "cleaned the finished shrink summaries up"); + } + Ok(()) +} + +/// Sends one summary and writes down what became of it. +#[tracing::instrument(skip_all, fields(id = %broadcast.id, chat_id = %broadcast.chat_id, date = %broadcast.shrink_date))] +async fn send_and_record(deps: BroadcastDeps<'_>, broadcast: ScheduledBroadcast) { + let config = &deps.config.daily_shrink.broadcast; + let id = broadcast.id; + let failures = broadcast.attempts; + let outcome = send(deps, &broadcast).await; + tracing::debug!(?outcome, "the shrink summary is dealt with"); + + // Only an ending is counted, and each one only once, so the outcomes add up to the number of + // summaries. A retry is a step, not an ending, and has a counter of its own. + let result = match outcome { + Outcome::Sent => finish(deps.repos, id, BroadcastState::Sent).await, + Outcome::Expired => finish(deps.repos, id, BroadcastState::Expired).await, + Outcome::Unreachable => finish(deps.repos, id, BroadcastState::Unreachable).await, + Outcome::Failed => finish(deps.repos, id, BroadcastState::Failed).await, + Outcome::Retry => { + metrics::DAILY_SHRINK.broadcast_retried(); + let next_attempt = Utc::now() + backoff(config.retry_delay, failures, config.max_retry_delay); + match deps.repos.broadcasts.postpone(id, next_attempt).await { + Ok(attempts) if attempts >= config.max_attempts => { + tracing::warn!(attempts = %attempts, "giving up on a shrink summary"); + finish(deps.repos, id, BroadcastState::Failed).await + }, + other => other.map(|_| ()), + } + }, + }; + if let Err(e) = result { + tracing::error!(error = format!("{e:#}"), "couldn't record the outcome of a shrink summary"); + } +} + +/// Stores the state a row ended in and counts that ending. Both happen here, so the table and the +/// counter always say the same thing. +async fn finish( + repos: &Repositories, + id: ScheduledBroadcastId, + state: BroadcastState, +) -> anyhow::Result<()> { + metrics::DAILY_SHRINK.broadcast_finished(state); + repos.broadcasts.finish(id, state).await +} + +/// Sends page 0 of the chat's shrink list for the day the row names, and says what became of it. +/// +/// The page comes from the same query the "next page" button uses, so what a chat reads first and +/// what it reads after tapping are one list rather than two orderings of it. +async fn send(deps: BroadcastDeps<'_>, broadcast: &ScheduledBroadcast) -> Outcome { + let BroadcastDeps { bot, repos, topics, config, .. } = deps; + let broadcast_config = &config.daily_shrink.broadcast; + + // A summary that waited this long has stopped being news, and the chat has the `shrinks` + // command for the history. Only a queue that fell behind can bring one here. + let age = (Utc::now() - broadcast.created_at).to_std().unwrap_or(Duration::ZERO); + if age > broadcast_config.max_age { + tracing::warn!(created_at = %broadcast.created_at, "the shrink summary got too old to be worth sending"); + return Outcome::Expired + } + + let chat = ChatIdKind::from(broadcast.chat_id); + let lang = resolve_broadcast_language(deps, &chat).await; + let lang_code = LanguageCode::new(lang.to_string()); + + let page = match shrinks_page_impl(repos, config, &chat, &lang_code, + ShrinkView::Broadcast, broadcast.shrink_date, Page::first()).await { + Ok(page) => page, + Err(e) => { + tracing::warn!(error = format!("{e:#}"), "couldn't render the shrink summary"); + return Outcome::Retry + }, + }; + // A single day by definition, so day-navigation (`adjacent`) is always `None`. + let keyboard = build_shrink_keyboard(ShrinkView::Broadcast, broadcast.shrink_date, + Page::first(), page.has_more_pages, None); + + // The throttled request wraps the payload, so the keyboard goes through the setter rather than + // the field the plain `Bot` exposes. + let mut request = bot.send_message(ChatId(broadcast.chat_id.value()), page.lines) + .parse_mode(Html) + .disable_link_preview(true); + if let Some(keyboard) = keyboard { + request = request.reply_markup(ReplyMarkup::InlineKeyboard(keyboard)); + } + // Nothing is being replied to here, so the topic has to be named outright. Left to itself the + // message would go to General — which a forum that keeps the bot elsewhere may well have + // closed, and posting into a closed topic is refused. + if let Some(topic) = topics.allowed(&chat).await.primary() { + request = request.message_thread_id(topic.into()); + } + + outcome_of(request.await.map(|_| ()), repos, broadcast).await +} + +/// Turns the answer of the Bot API into an outcome, remembering what it says about the chat. +async fn outcome_of( + result: Result<(), RequestError>, + repos: &Repositories, + broadcast: &ScheduledBroadcast, +) -> Outcome { + let error = match result { + Ok(()) => return Outcome::Sent, + Err(e) => e, + }; + + if !is_chat_unreachable(&error) { + if is_final(&error) { + tracing::warn!(error = %error, "the shrink summary can't be sent to this chat at all"); + return Outcome::Failed + } + tracing::warn!(error = %error, "couldn't notify the chat about the shrinks"); + return Outcome::Retry + } + + // Marking is best-effort: a chat that stays unmarked is merely queued again tomorrow. + tracing::info!(error = %error, "the chat is unreachable, skipping it from now on"); + repos.chats.mark_unreachable(&broadcast.chat_id) + .await + .unwrap_or_else(|e| tracing::warn!(error = format!("{e:#}"), "couldn't mark the chat as unreachable")); + Outcome::Unreachable +} + +/// The three errors teloxide has no variant for, in the wording Telegram actually sends. The first +/// two are what a modern group returns instead of [`ApiError::BotKicked`]; the last one is a bot +/// that is still a member but was muted by an admin. +const UNREACHABLE_ERROR_TEXTS: [&str; 3] = [ + "bot was kicked from the group chat", + "bot is not a member of the group chat", + "have no rights to send a message", +]; + +/// Whether a failed send means the bot can't post to that chat at all, as opposed to a hiccup worth +/// retrying. +/// +/// Rate limits, timeouts and network errors are all transient, so they never mark a chat. Neither +/// does [`RequestError::MigrateToChatId`]: the chat is alive and well under its new id, and the +/// `migration_handler` repoints its row on the service message Telegram sends alongside. +fn is_chat_unreachable(error: &RequestError) -> bool { + let RequestError::Api(api_err) = error else { + return false + }; + match api_err { + ApiError::BotBlocked + | ApiError::BotKicked + | ApiError::BotKickedFromSupergroup + | ApiError::BotKickedFromChannel + | ApiError::ChatNotFound + | ApiError::GroupDeactivated + | ApiError::UserDeactivated + | ApiError::NotEnoughRightsToPostMessages => true, + // Telegram keeps adding wordings teloxide doesn't know yet, and the ones a group hits most + // often are among them, so the raw text is the only thing left to look at. + ApiError::Unknown(text) => { + let text = text.to_lowercase(); + UNREACHABLE_ERROR_TEXTS.iter().any(|known| text.contains(known)) + } + _ => false + } +} + +/// Whether retrying could ever help. A rejection teloxide has a variant for is one Telegram thought +/// about and refused, so the same payload gets the same answer, and spending three attempts on it +/// costs three requests per chat — which at a few hundred thousand chats is the difference between +/// a hiccup and an outage. `Unknown` stays retryable: Telegram's own 5xx answers arrive that way. +fn is_final(error: &RequestError) -> bool { + matches!(error, RequestError::Api(api) if !matches!(api, ApiError::Unknown(_))) +} + +/// Picks the language for a chat's summary: the chat-wide override wins; otherwise, when the +/// `getMany` toggle is on, the most popular language among the chat's players; English otherwise. +#[tracing::instrument(skip_all)] +async fn resolve_broadcast_language(deps: BroadcastDeps<'_>, chat: &ChatIdKind) -> SupportedLanguage { + let BroadcastDeps { repos, language_service, config, .. } = deps; + match repos.chats.get_chat_language(chat).await { + Ok(Some(lang)) => { + metrics::BROADCAST_LANGUAGE.decided_by_chat(); + return lang + } + Ok(None) => {} + Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't read the language of the chat"), + } + + if config.features.most_popular_language_enabled { + let uids: Vec = repos.dicks.get_player_uids(chat).await + .inspect_err(|e| tracing::warn!(error = format!("{e:#}"), "couldn't list the players of the chat")) + .unwrap_or_default() + .into_iter() + .map(Into::into) + .collect(); + if let Some(lang) = language_service.popular_language(&uids).await { + metrics::BROADCAST_LANGUAGE.decided_by_tally(); + return lang; + } + } + metrics::BROADCAST_LANGUAGE.defaulted(); + SupportedLanguage::EN +} + +#[cfg(test)] +mod tests { + use teloxide::{ApiError, RequestError}; + use super::is_chat_unreachable; + + #[test] + fn known_api_errors_make_a_chat_unreachable() { + for err in [ + ApiError::BotBlocked, + ApiError::BotKicked, + ApiError::BotKickedFromSupergroup, + ApiError::BotKickedFromChannel, + ApiError::ChatNotFound, + ApiError::GroupDeactivated, + ApiError::UserDeactivated, + ApiError::NotEnoughRightsToPostMessages, + ] { + assert!(is_chat_unreachable(&RequestError::Api(err.clone())), "{err:?} should mark the chat"); + } + } + + /// The wordings a group really gets: teloxide has no variant for any of them, so they arrive as + /// `Unknown` and only the text tells them apart from a transient error. + #[test] + fn unknown_api_errors_are_matched_by_their_text() { + for text in [ + "Forbidden: bot was kicked from the group chat", + "Forbidden: bot is not a member of the group chat", + "Bad Request: have no rights to send a message", + ] { + let err = RequestError::Api(ApiError::Unknown(text.to_owned())); + assert!(is_chat_unreachable(&err), "{text:?} should mark the chat"); + } + } + + #[test] + fn transient_errors_leave_the_chat_alone() { + let unknown = RequestError::Api(ApiError::Unknown("Bad Request: message is too long".to_owned())); + assert!(!is_chat_unreachable(&unknown)); + + let too_long = RequestError::Api(ApiError::MessageIsTooLong); + assert!(!is_chat_unreachable(&too_long)); + + let retry_after = RequestError::RetryAfter(teloxide::types::Seconds::from_seconds(30)); + assert!(!is_chat_unreachable(&retry_after)); + + // A migrated chat is alive under its new id; the migration handler repoints its row. + let migrated = RequestError::MigrateToChatId(teloxide::types::ChatId(-100)); + assert!(!is_chat_unreachable(&migrated)); + } +} diff --git a/src/scheduler/deletions.rs b/src/scheduler/deletions.rs index 015d618..6e4e0be 100644 --- a/src/scheduler/deletions.rs +++ b/src/scheduler/deletions.rs @@ -14,9 +14,10 @@ use crate::config::MessageGroup; use domain_types::traits::ApproxInto; use crate::cache::Cache; use crate::handlers::rights; -use crate::domain::primitives::{AttemptsCount, ScheduledDeletionId}; +use crate::domain::primitives::ScheduledDeletionId; use crate::metrics; use crate::repo::{DeletionState, DeletionTarget, MessageKind, Repositories, ScheduledDeletion}; +use super::backoff; /// The age at which Telegram stops letting a bot delete a message. This is the real limit; /// [`crate::config::MAX_DELAY`] caps the delays an hour below it. Nothing is scheduled this late, @@ -88,6 +89,7 @@ async fn act_and_record( let kind = deletion.kind; let failures = deletion.attempts; let outcome = act(bot, cache, config, bot_admin_ttl, deletion).await; + tracing::debug!(id = %id, group = %group, kind = %kind, ?outcome, "the message is dealt with"); // Only an ending is counted, and each one only once, so the outcomes add up to the number of // messages. A warning and a retry are steps, not endings; retries have their own counter. @@ -127,14 +129,6 @@ async fn finish( repos.deletions.finish(id, state).await } -/// How long a message rests before the next attempt: the base delay doubled once per failure it -/// already has, up to `max`. A chat that answers slowly is asked less and less often, instead of at -/// a steady beat for as many attempts as it is given. -fn backoff(base: Duration, failures: AttemptsCount, max: Duration) -> Duration { - let factor = 1u32.checked_shl(failures.value()).unwrap_or(u32::MAX); - base.saturating_mul(factor).min(max) -} - /// Removes the rows that were finished long enough ago, and reports what is left. /// /// Separate from the worker on purpose: the finished rows are the only account of what the worker @@ -144,6 +138,7 @@ fn backoff(base: Duration, failures: AttemptsCount, max: Duration) -> Duration { #[tracing::instrument(skip_all)] pub async fn clean_finished_deletions(repos: &Repositories, retention: Duration) -> anyhow::Result<()> { let older_than = Utc::now() - retention; + tracing::debug!(%older_than, ?retention, "cleaning the finished self-destructions up"); let removed = repos.deletions.delete_finished(older_than).await?; if removed > 0 { tracing::info!(removed, "cleaned the finished self-destructions up"); @@ -296,25 +291,6 @@ fn is_final(error: &RequestError) -> bool { mod tests { use super::*; - const MAX: Duration = Duration::from_secs(60 * 60); - - #[test] - fn the_back_off_doubles_with_every_failure() { - let base = Duration::from_secs(60); - assert_eq!(backoff(base, AttemptsCount::new(0), MAX), Duration::from_secs(60)); - assert_eq!(backoff(base, AttemptsCount::new(1), MAX), Duration::from_secs(120)); - assert_eq!(backoff(base, AttemptsCount::new(2), MAX), Duration::from_secs(240)); - assert_eq!(backoff(base, AttemptsCount::new(3), MAX), Duration::from_secs(480)); - } - - #[test] - fn the_back_off_never_grows_past_its_cap() { - let base = Duration::from_secs(60); - assert_eq!(backoff(base, AttemptsCount::new(30), MAX), MAX); - // The shift that would overflow must give the cap, not a wrapped-around delay of nothing. - assert_eq!(backoff(base, AttemptsCount::new(u32::MAX), MAX), MAX); - } - /// A message someone else removed used to be warned first and only found missing a grace /// period later, at the cost of two requests and a warn-level line for a normal event. #[test] diff --git a/src/scheduler/mod.rs b/src/scheduler/mod.rs index 9dce338..ee3880a 100644 --- a/src/scheduler/mod.rs +++ b/src/scheduler/mod.rs @@ -1,11 +1,14 @@ mod shrink; mod deletions; +mod broadcasts; -use domain_types::traits::SaturatingInto; +use std::time::Duration; use teloxide::Bot; use teloxide::adaptors::throttle::{Settings, Throttle}; +use domain_types::traits::SaturatingInto; use crate::cache::Cache; use crate::config::{get_env_value_or_default, AppConfig, ThrottleConfig}; +use crate::domain::primitives::AttemptsCount; use crate::handlers::utils::date::duration_till_next_day; use crate::metrics; use crate::repo::Repositories; @@ -13,6 +16,7 @@ use crate::topics::TopicPolicy; use crate::users::LanguageService; use shrink::run_daily_shrink; use deletions::{clean_finished_deletions, run_pending_deletions}; +use broadcasts::{clean_finished_broadcasts, run_pending_broadcasts, BroadcastDeps}; /// A bot that keeps the schedulers inside Telegram's rate limits. /// @@ -32,28 +36,23 @@ pub fn throttled(bot: Bot, config: ThrottleConfig) -> Throttle { } /// Spawns a detached, best-effort task that runs the daily shrink at every UTC midnight. No-op when -/// the feature is disabled. Like the self-destruction scheduler, it isn't persisted — a restart just -/// resumes from the next midnight; failures are logged and never abort the loop. -pub fn spawn_daily_shrink( - bot: Throttle, - repos: Repositories, - language_service: LanguageService, - topics: TopicPolicy, - config: AppConfig, -) { +/// the feature is disabled. The run itself isn't persisted — a restart just resumes from the next +/// midnight; failures are logged and never abort the loop. +/// +/// What the run produces *is* persisted: the summaries it owes are rows, written by the same +/// statement that shrank the dicks, so nothing here has to survive for a chat to be notified. +pub fn spawn_daily_shrink(repos: Repositories, config: AppConfig) { if !config.daily_shrink.enabled() { tracing::info!("the daily shrink is disabled (set DAILY_SHRINK_RATIO and DAILY_SHRINK_INACTIVITY_DAYS to enable it)"); return; } + tracing::info!(batch_size = %config.daily_shrink.batch_size, ratio = %config.daily_shrink.ratio, + inactivity_days = %config.daily_shrink.inactivity_days, "the daily shrink scheduler has started"); tokio::spawn(metrics::TASK_DAILY_SHRINK.instrument(async move { - // The throttle queue lives in memory only: a restart during the broadcast drops the - // notifications that still wait, and there is no way to resume them. - // TODO: [#154] Make broadcasting of messages durable by storing tasks in the database - // // A failed run is logged and forgotten: the next midnight tries again, and one bad day // must not stop the scheduler for good. let run = || async { - run_daily_shrink(bot.clone(), repos.clone(), language_service.clone(), topics.clone(), config.clone()) + run_daily_shrink(repos.clone(), config.clone()) .await .unwrap_or_else(|e| tracing::error!(error = format!("{e:#}"), "the daily shrink run failed")) }; @@ -69,6 +68,7 @@ pub fn spawn_daily_shrink( tracing::error!("couldn't compute a valid duration till the next UTC midnight, stopping the daily shrink scheduler"); return; }; + tracing::debug!(sleeping_for = ?till_next_day, "waiting for the next UTC midnight"); tokio::time::sleep(till_next_day).await; run().await; @@ -76,6 +76,76 @@ pub fn spawn_daily_shrink( })); } +/// Spawns the task that sends the shrink summaries the chats are owed. No-op when the daily shrink +/// is disabled, since nothing would ever write a row. +/// +/// Unlike the shrink above, this one survives a restart: what it acts on are rows, and the tick +/// after the restart claims every summary that fell due meanwhile — which is what makes a broadcast +/// to a few hundred thousand chats possible at all. +pub fn spawn_broadcast_worker( + bot: Throttle, + repos: Repositories, + language_service: LanguageService, + topics: TopicPolicy, + config: AppConfig, +) { + if !config.daily_shrink.enabled() { + return; + } + // Published so that a graph of the batch size can be read against the limit it may reach, + // instead of against a number written into the dashboard. + metrics::DAILY_SHRINK_BROADCAST_BATCH_LIMIT.set(i64::from(config.daily_shrink.broadcast.batch_size)); + tracing::info!(poll_interval = ?config.daily_shrink.broadcast.poll_interval, + batch_size = %config.daily_shrink.broadcast.batch_size, + concurrency = %config.daily_shrink.broadcast.concurrency, + "the shrink broadcast worker has started"); + tokio::spawn(metrics::TASK_DAILY_SHRINK_BROADCAST.instrument(async move { + let mut ticker = tokio::time::interval(config.daily_shrink.broadcast.poll_interval); + loop { + ticker.tick().await; + + // A failed tick is logged and forgotten: the rows are still there, and the next tick + // picks them up. Only the count is skipped, as it comes from the same database. + let deps = BroadcastDeps { + bot: &bot, repos: &repos, language_service: &language_service, + topics: &topics, config: &config, + }; + if let Err(e) = run_pending_broadcasts(deps).await { + tracing::error!(error = format!("{e:#}"), "a shrink broadcast run failed"); + continue; + } + report_shrink_queue(&repos).await; + } + })); +} + +/// Spawns the task that clears the finished rows out of the broadcast queue's table. Separate from +/// the worker so that the history of what it did can be kept (and read) for as long as the +/// retention says — zero keeps it for ever, which is what to set while debugging the worker itself. +pub fn spawn_broadcast_cleaner(repos: Repositories, config: AppConfig) { + let retention = config.daily_shrink.broadcast.retention; + if !config.daily_shrink.enabled() { + return; + } + if retention.is_zero() { + tracing::info!(variable = "DAILY_SHRINK_BROADCAST_TABLE_CLEANING_DELAY_DAYS", + "the finished shrink summaries are kept for ever"); + return; + } + tracing::info!(?retention, "the shrink broadcast cleaner has started"); + tokio::spawn(metrics::TASK_DAILY_SHRINK_BROADCAST_CLEANING.instrument(async move { + // Runs as often as it keeps, so a row lives between one and two retention periods. There's + // nothing to gain from looking more often: nothing becomes stale in between. + let mut ticker = tokio::time::interval(retention); + loop { + ticker.tick().await; + + clean_finished_broadcasts(&repos, retention).await + .unwrap_or_else(|e| tracing::error!(error = format!("{e:#}"), "the cleaning of the finished shrink summaries failed")); + } + })); +} + /// Spawns the task that removes the messages whose self-destruction has come due. No-op when every /// group is permanent. Unlike the two schedulers above, this one survives a restart: the messages /// it acts on are rows, and the tick after the restart finds every one that fell due meanwhile. @@ -89,6 +159,9 @@ pub fn spawn_deletion_worker(bot: Throttle, repos: Repositories, cache: Cac // Published so that a graph of the batch size can be read against the limit it may reach, // instead of against a number written into the dashboard. metrics::SELF_DESTRUCTION_BATCH_LIMIT.set(i64::from(self_destruction.batch_size)); + tracing::info!(poll_interval = ?self_destruction.poll_interval, batch_size = %self_destruction.batch_size, + concurrency = %self_destruction.concurrency, mode = %self_destruction.mode, + "the self-destruction worker has started"); tokio::spawn(metrics::TASK_SELF_DESTRUCTION.instrument(async move { let mut ticker = tokio::time::interval(self_destruction.poll_interval); loop { @@ -110,9 +183,15 @@ pub fn spawn_deletion_worker(bot: Throttle, repos: Repositories, cache: Cac /// zero keeps it for ever, which is what to set while debugging the worker itself. pub fn spawn_deletion_cleaner(repos: Repositories, config: AppConfig) { let retention = config.self_destruction.retention; - if !config.self_destruction.enabled() || retention.is_zero() { + if !config.self_destruction.enabled() { + return; + } + if retention.is_zero() { + tracing::info!(variable = "MSG_SELFDESTRUCT_TABLE_CLEANING_DELAY_DAYS", + "the finished self-destructions are kept for ever"); return; } + tracing::info!(?retention, "the self-destruction cleaner has started"); tokio::spawn(metrics::TASK_SELF_DESTRUCTION_CLEANING.instrument(async move { // Runs as often as it keeps, so a row lives between one and two retention periods. There's // nothing to gain from looking more often: nothing becomes stale in between. @@ -127,6 +206,40 @@ pub fn spawn_deletion_cleaner(repos: Repositories, config: AppConfig) { })); } +/// How long a row rests before the next attempt: the base delay doubled once per failure it already +/// has, up to `max`. A chat that answers slowly is asked less and less often, instead of at a steady +/// beat for as many attempts as it is given. +fn backoff(base: Duration, failures: AttemptsCount, max: Duration) -> Duration { + let factor = 1u32.checked_shl(failures.value()).unwrap_or(u32::MAX); + base.saturating_mul(factor).min(max) +} + +/// Publishes how much the broadcast queue still owes and when the last shrink was. +/// +/// Only these two, and only from the worker's tick: they are what the alerts read, and vmalert +/// can't ask the database itself. Everything a human looks at — which chats failed and why, the +/// states over time — is a panel over `Scheduled_Shrink_Broadcasts` instead, which costs nothing +/// when nobody is looking at it. +/// +/// The day of the last shrink is a gauge rather than a counter because it has to survive a restart: +/// a counter incremented once a day reads zero both when nothing happened and when nobody scraped +/// it in time, and there is no telling those apart afterwards. +/// +/// A failure here loses one sample of a gauge and nothing else — the queue, the rows and the worker +/// are untouched, and the next tick publishes again — so it is a `warn`. It also runs every few +/// seconds, and a database that is down has already been reported by the run that failed. +async fn report_shrink_queue(repos: &Repositories) { + match repos.broadcasts.count_pending().await { + Ok(pending) => metrics::DAILY_SHRINK_BROADCAST_PENDING.set(pending.saturating_into()), + Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't count the pending shrink summaries"), + } + match repos.shrinks.get_last_shrink_timestamp().await { + Ok(Some(at)) => metrics::DAILY_SHRINK_LAST_RUN_TIMESTAMP.set(at.timestamp()), + Ok(None) => {}, + Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't read the time of the last shrink"), + } +} + /// Publishes the depth of the queue and of its backlog of finished rows. Both are read from the /// same database the run just used, so a failure here is only logged. async fn report_queue(repos: &Repositories) { @@ -139,3 +252,27 @@ async fn report_queue(repos: &Repositories) { Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't count the finished self-destructions"), } } + +#[cfg(test)] +mod tests { + use super::*; + + const MAX: Duration = Duration::from_hours(1); + + #[test] + fn the_back_off_doubles_with_every_failure() { + let base = Duration::from_secs(60); + assert_eq!(backoff(base, AttemptsCount::new(0), MAX), Duration::from_secs(60)); + assert_eq!(backoff(base, AttemptsCount::new(1), MAX), Duration::from_secs(120)); + assert_eq!(backoff(base, AttemptsCount::new(2), MAX), Duration::from_secs(240)); + assert_eq!(backoff(base, AttemptsCount::new(3), MAX), Duration::from_secs(480)); + } + + #[test] + fn the_back_off_never_grows_past_its_cap() { + let base = Duration::from_secs(60); + assert_eq!(backoff(base, AttemptsCount::new(30), MAX), MAX); + // The shift that would overflow must give the cap, not a wrapped-around delay of nothing. + assert_eq!(backoff(base, AttemptsCount::new(u32::MAX), MAX), MAX); + } +} diff --git a/src/scheduler/shrink.rs b/src/scheduler/shrink.rs index 8c3a52a..e7ef4ce 100644 --- a/src/scheduler/shrink.rs +++ b/src/scheduler/shrink.rs @@ -1,292 +1,70 @@ -use std::collections::HashMap; use autometrics::autometrics; -use chrono::Utc; -use domain_types::traits::SaturatingInto; -use teloxide::{ApiError, Bot, RequestError}; -use teloxide::adaptors::Throttle; -use teloxide::payloads::SendMessageSetters; -use teloxide::requests::Requester; -use teloxide::sugar::request::RequestLinkPreviewExt; -use teloxide::types::{ChatId, ReplyMarkup, UserId as TeloxideUserId}; -use teloxide::types::ParseMode::Html; use crate::config::AppConfig; -use crate::domain::primitives::{LanguageCode, Page, SupportedLanguage}; -use crate::domain::primitives::chat::{ChatIdKind, TelegramChatId}; -use crate::handlers::shrink::{build_shrink_keyboard, render_shrinks_page, ShrinkView}; use crate::metrics; -use crate::repo::{Repositories, ShrinkEvent}; -use crate::topics::TopicPolicy; -use crate::users::LanguageService; +use crate::repo::{Repositories, ShrinkBatchOutcome}; -/// Runs the daily shrink: applies the decay in one DB statement, then broadcasts a per-chat summary -/// to every affected group chat. Inline-only chats (no messageable `chat_id`) get no message. Their -/// members see the events via the `shrinks` inline command. Their victims are still counted, under -/// the `inline_only` label of [`metrics::DAILY_SHRINK`]. -#[autometrics] -#[tracing::instrument(skip_all)] -pub async fn run_daily_shrink( - bot: Throttle, - repos: Repositories, - language_service: LanguageService, - topics: TopicPolicy, - config: AppConfig, -) -> anyhow::Result<()> { - let events = repos.shrinks - .perform_daily_shrink( - config.daily_shrink.ratio, - config.daily_shrink.inactivity_days, - config.daily_shrink.ramp_up_days, - ) - .await - .inspect_err(|_| metrics::DAILY_SHRINK.run_failed())?; - if events.is_empty() { - metrics::DAILY_SHRINK.run_empty(); - tracing::info!("nothing to shrink today"); - return Ok(()); - } - metrics::DAILY_SHRINK.run_succeeded(); - - // The scheduler only ever wakes up at UTC midnight (see `spawn_daily_shrink`), and the shrinks - // just logged carry Postgres's `current_date` — also UTC — so this is the exact day they belong - // to. Captured once so every chat's broadcast pins the same date its shrinks were logged under. - let today = Utc::now().date_naive(); - - let total: u64 = events.len().saturating_into(); - let mut by_chat: HashMap> = HashMap::new(); - // Chats the bot is known to have lost access to are dropped here rather than at the broadcast: - // there's no point holding their events, and skipping is counted per chat, not per victim. - let mut unreachable_victims_count_by_chat = HashMap::new(); - for event in events { - match event.messageable_chat_id { - Some(chat_id) if event.is_unreachable => { - *unreachable_victims_count_by_chat.entry(chat_id).or_default() += 1; - } - Some(chat_id) => by_chat.entry(chat_id).or_default().push(event), - None => {} - } - } - let to_broadcast_count: u64 = by_chat.values() - .map(|victims| -> u64 { victims.len().saturating_into() }) - .sum(); - let unreachable_victims_count: u64 = unreachable_victims_count_by_chat.values().sum(); - metrics::DAILY_SHRINK.victims_to_broadcast(to_broadcast_count); - metrics::DAILY_SHRINK.victims_unreachable(unreachable_victims_count); - metrics::DAILY_SHRINK.victims_inline_only(total - to_broadcast_count - unreachable_victims_count); - metrics::DAILY_SHRINK.broadcast_skipped(unreachable_victims_count_by_chat.len().saturating_into()); - if !unreachable_victims_count_by_chat.is_empty() { - tracing::info!(chats = unreachable_victims_count_by_chat.len(), victims = unreachable_victims_count, - "skipped the unreachable chats"); - } - - let deps = BroadcastDeps { - bot: &bot, repos: &repos, language_service: &language_service, topics: &topics, config: &config, - }; - for (chat_id, victims) in by_chat { - match broadcast_shrink(&deps, chat_id, today, &victims).await { - Ok(_) => metrics::DAILY_SHRINK.broadcast_sent(), - Err(e) => handle_broadcast_error(&repos, chat_id, e).await, - } - } - Ok(()) -} - -/// Logs a failed broadcast and, when Telegram says the bot can't post to that chat at all, marks -/// the chat so the next runs don't try again. +/// Runs the daily shrink: applies the decay to every stale dick and queues one summary per chat the +/// bot can post to. Nothing is sent from here — the queue's worker does that, at its own pace. /// -/// Marking is best-effort on purpose: a chat that stays unmarked is merely retried tomorrow, -/// and one broken chat must not abort the rest of the broadcast. -#[tracing::instrument(skip_all, fields(chat_id = %chat_id))] -async fn handle_broadcast_error(repos: &Repositories, chat_id: TelegramChatId, err: anyhow::Error) { - if !is_chat_unreachable(&err) { - metrics::DAILY_SHRINK.broadcast_failed(); - tracing::warn!(error = format!("{err:#}"), "couldn't notify the chat about the shrinks"); - return; - } - metrics::DAILY_SHRINK.broadcast_unreachable(); - tracing::info!(error = format!("{err:#}"), "the chat is unreachable, skipping it from now on"); - repos.chats.mark_unreachable(&chat_id) - .await - .unwrap_or_else(|e| tracing::warn!(error = format!("{e:#}"), "couldn't mark the chat as unreachable")); -} - -/// The three errors teloxide has no variant for, in the wording Telegram actually sends. The first -/// two are what a modern group returns instead of [`ApiError::BotKicked`]; the last one is a bot -/// that is still a member but was muted by an admin. -const UNREACHABLE_ERROR_TEXTS: [&str; 3] = [ - "bot was kicked from the group chat", - "bot is not a member of the group chat", - "have no rights to send a message", -]; - -/// Whether a failed send means the bot can't post to that chat at all, as opposed to a hiccup worth -/// retrying tomorrow. +/// The chats are walked in batches, so neither the locks nor a failure covers more than a batch, +/// and the run returns in minutes however many chats there are. That is what keeps the scheduler's +/// loop able to reach the next midnight. /// -/// Rate limits, timeouts and network errors are all transient, so they never mark a chat. Neither -/// does [`RequestError::MigrateToChatId`]: the chat is alive and well under its new id, and the -/// `migration_handler` repoints its row on the service message Telegram sends alongside. -fn is_chat_unreachable(err: &anyhow::Error) -> bool { - let Some(RequestError::Api(api_err)) = err.downcast_ref::() else { - return false - }; - match api_err { - ApiError::BotBlocked - | ApiError::BotKicked - | ApiError::BotKickedFromSupergroup - | ApiError::BotKickedFromChannel - | ApiError::ChatNotFound - | ApiError::GroupDeactivated - | ApiError::UserDeactivated - | ApiError::NotEnoughRightsToPostMessages => true, - // Telegram keeps adding wordings teloxide doesn't know yet, and the ones a group hits most - // often are among them, so the raw text is the only thing left to look at. - ApiError::Unknown(text) => { - let text = text.to_lowercase(); - UNREACHABLE_ERROR_TEXTS.iter().any(|known| text.contains(known)) - } - _ => false - } -} - -/// Sends page 0 of the chat's shrink list, rendered straight from `victims` — no query, since the -/// daily job already holds exactly this data (and for most chats it's the whole list anyway). -/// Pages 1+ (only reachable by an actual button press) fall back to [`shrinks_page_impl`], pinned -/// to `date` so a click on day D+1 still shows day D's shrinks. +/// Inline-only chats (no messageable `chat_id`) get no summary — their members see the events via +/// the `shrinks` inline command — and neither do the ones the bot is known to have lost access to. +/// Both are counted, under the `inline_only` and `unreachable` labels of [`metrics::DAILY_SHRINK`]. #[autometrics] -#[tracing::instrument(skip_all, fields(chat_id = %chat_id, date = %date, victims = victims.len()))] -async fn broadcast_shrink( - deps: &BroadcastDeps<'_>, - chat_id: TelegramChatId, - date: chrono::NaiveDate, - victims: &[ShrinkEvent], -) -> anyhow::Result<()> { - let BroadcastDeps { bot, config, topics, .. } = deps; - let chat = ChatIdKind::from(chat_id); - let lang = resolve_broadcast_language(deps, &chat).await; - let lang_code = LanguageCode::new(lang.to_string()); - - let has_more_pages = victims.len() > usize::from(config.top_limit); - let page = render_shrinks_page(victims, config, &lang_code, ShrinkView::Broadcast, has_more_pages); - // A single day by definition, so day-navigation (`adjacent`) is always `None`. - let keyboard = build_shrink_keyboard(ShrinkView::Broadcast, date, Page::first(), page.has_more_pages, None); - - // The throttled request wraps the payload, so the keyboard goes through the setter rather than - // the field the plain `Bot` exposes. - let mut request = bot.send_message(ChatId(chat_id.value()), page.lines) - .parse_mode(Html) - .disable_link_preview(true); - if let Some(keyboard) = keyboard { - request = request.reply_markup(ReplyMarkup::InlineKeyboard(keyboard)); - } - // Nothing is being replied to here, so the topic has to be named outright. Left to itself the - // message would go to General — which a forum that keeps the bot elsewhere may well have - // closed, and posting into a closed topic is refused. - if let Some(topic) = topics.allowed(&chat).await.primary() { - request = request.message_thread_id(topic.into()); - } - request.await?; - Ok(()) -} - -/// The services every chat's broadcast needs, bundled so the per-chat calls stay readable. -struct BroadcastDeps<'a> { - bot: &'a Throttle, - repos: &'a Repositories, - language_service: &'a LanguageService, - topics: &'a TopicPolicy, - config: &'a AppConfig, -} - -/// Picks the language for a chat's broadcast: the chat-wide override wins; otherwise, when the -/// `getMany` toggle is on, the most popular language among the chat's players; English otherwise. -#[tracing::instrument(skip_all, fields(chat_id = %chat))] -async fn resolve_broadcast_language(deps: &BroadcastDeps<'_>, chat: &ChatIdKind) -> SupportedLanguage { - let BroadcastDeps { repos, language_service, config, .. } = deps; - match repos.chats.get_chat_language(chat).await { - Ok(Some(lang)) => { - metrics::BROADCAST_LANGUAGE.decided_by_chat(); - return lang - } - Ok(None) => {} - Err(e) => tracing::warn!(error = format!("{e:#}"), "couldn't read the language of the chat"), - } - - if config.features.most_popular_language_enabled { - let uids: Vec = repos.dicks.get_player_uids(chat).await - .inspect_err(|e| tracing::warn!(error = format!("{e:#}"), "couldn't list the players of the chat")) - .unwrap_or_default() - .into_iter() - .map(Into::into) - .collect(); - if let Some(lang) = language_service.popular_language(&uids).await { - metrics::BROADCAST_LANGUAGE.decided_by_tally(); - return lang; - } - } - metrics::BROADCAST_LANGUAGE.defaulted(); - SupportedLanguage::EN -} - -#[cfg(test)] -mod tests { - use teloxide::{ApiError, RequestError}; - use super::is_chat_unreachable; - - fn api_error(err: ApiError) -> anyhow::Error { - RequestError::Api(err).into() - } - - #[test] - fn known_api_errors_make_a_chat_unreachable() { - for err in [ - ApiError::BotBlocked, - ApiError::BotKicked, - ApiError::BotKickedFromSupergroup, - ApiError::BotKickedFromChannel, - ApiError::ChatNotFound, - ApiError::GroupDeactivated, - ApiError::UserDeactivated, - ApiError::NotEnoughRightsToPostMessages, - ] { - assert!(is_chat_unreachable(&api_error(err.clone())), "{err:?} should mark the chat"); - } - } - - /// The wordings a group really gets: teloxide has no variant for any of them, so they arrive as - /// `Unknown` and only the text tells them apart from a transient error. - #[test] - fn unknown_api_errors_are_matched_by_their_text() { - for text in [ - "Forbidden: bot was kicked from the group chat", - "Forbidden: bot is not a member of the group chat", - "Bad Request: have no rights to send a message", - ] { - let err = api_error(ApiError::Unknown(text.to_owned())); - assert!(is_chat_unreachable(&err), "{text:?} should mark the chat"); +#[tracing::instrument(skip_all)] +pub async fn run_daily_shrink(repos: Repositories, config: AppConfig) -> anyhow::Result<()> { + let shrink_config = &config.daily_shrink; + let mut total = ShrinkBatchOutcome::default(); + let mut chats = 0usize; + let mut failed_batches = 0u32; + let mut after = None; + + // A batch of chats is read, shrunk and forgotten before the next one is asked for, so the run + // holds one batch at a time however many chats there are. + loop { + let batch = repos.shrinks.select_chats_batch(after, shrink_config.batch_size) + .await + .inspect_err(|_| metrics::DAILY_SHRINK.run_failed())?; + let Some(last) = batch.last().copied() else { break }; + tracing::debug!(chats = batch.len(), up_to = %last, "shrinking a batch of chats"); + after = Some(last); + chats += batch.len(); + + match repos.shrinks.perform_daily_shrink(&batch, shrink_config.ratio, + shrink_config.inactivity_days, shrink_config.ramp_up_days).await { + // A batch that fails takes its own chats down and nothing else: the ones already + // shrunk keep their summaries, and the rest are still ahead. Nothing retries it, so + // those chats have lost the day — an error, not a warning. + Err(e) => { + failed_batches += 1; + tracing::error!(chats = batch.len(), error = format!("{e:#}"), "a batch of the daily shrink failed"); + }, + Ok(outcome) => total += outcome, } } - #[test] - fn transient_errors_leave_the_chat_alone() { - let unknown = api_error(ApiError::Unknown("Bad Request: message is too long".to_owned())); - assert!(!is_chat_unreachable(&unknown)); - - let too_long = api_error(ApiError::MessageIsTooLong); - assert!(!is_chat_unreachable(&too_long)); - - let retry_after = anyhow::Error::from(RequestError::RetryAfter( - teloxide::types::Seconds::from_seconds(30))); - assert!(!is_chat_unreachable(&retry_after)); - - // A migrated chat is alive under its new id; the migration handler repoints its row. - let migrated = anyhow::Error::from(RequestError::MigrateToChatId(teloxide::types::ChatId(-100))); - assert!(!is_chat_unreachable(&migrated)); - } - - /// Anything that isn't a `RequestError` at all — the broadcast can also fail before the send, - /// e.g. while reading the chat's language. - #[test] - fn non_telegram_errors_leave_the_chat_alone() { - let err = anyhow::anyhow!("couldn't render the page"); - assert!(!is_chat_unreachable(&err)); + metrics::DAILY_SHRINK.victims_to_broadcast(total.to_broadcast.value()); + metrics::DAILY_SHRINK.victims_inline_only(total.inline_only.value()); + metrics::DAILY_SHRINK.victims_unreachable(total.unreachable.value()); + metrics::DAILY_SHRINK.broadcast_skipped(total.chats_skipped.value()); + + // A run that lost a batch is a failed run even if the others went through: a partial day must + // not read like a whole one. Each batch has already said so in its own line, with the error; + // this only counts the day. + if failed_batches > 0 { + metrics::DAILY_SHRINK.run_failed(); + } else if total.victims.value() == 0 { + metrics::DAILY_SHRINK.run_empty(); + tracing::info!(chats, "nothing to shrink today"); + return Ok(()) + } else { + metrics::DAILY_SHRINK.run_succeeded(); } + tracing::info!(chats, failed_batches, victims = total.victims.value(), + queued = total.chats_queued.value(), skipped = total.chats_skipped.value(), + "the daily shrink is done"); + Ok(()) } diff --git a/src/telegram_observer.rs b/src/telegram_observer.rs index 165856b..880d0ae 100644 --- a/src/telegram_observer.rs +++ b/src/telegram_observer.rs @@ -4,7 +4,7 @@ use teloxide::observer::{RequestBody, RequestObservation, RequestObserver}; use teloxide::{ApiError, RequestError}; use tracing::Span; use crate::error_handler::classify; -use crate::metrics::TELEGRAM_REQUEST_DURATION; +use crate::metrics::{TELEGRAM_REQUEST_DURATION, TELEGRAM_REQUEST_ERRORS}; /// Watches every request the bot sends to the Telegram Bot API and turns it into three signals: /// the `telegram_request_duration_seconds` histogram, a client span the request's latency can be @@ -39,6 +39,12 @@ impl RequestObservation for PendingRequest { fn on_response(self: Box, elapsed: Duration, outcome: Result<(), &RequestError>) { let label = outcome.map_or_else(classify, |()| "ok"); TELEGRAM_REQUEST_DURATION.record(self.method, label, elapsed.as_secs_f64()); + // One classification feeds both, so the histogram's `outcome` and the counter's `kind` can + // never disagree. Counted here rather than at the dispatcher because this sits below every + // adaptor, and so sees the schedulers' requests too — which the dispatcher never does. + if outcome.is_err() { + TELEGRAM_REQUEST_ERRORS.record(label); + } // `ApiError::Unknown` is the answer Telegram gives when it dislikes something about the // payload itself — a broken entity, an over-long text — and the message alone never says @@ -78,14 +84,42 @@ mod tests { assert_samples("GetMe", "ok", 1); } + /// `telegram_request_errors_total` carries only a `kind`, so unlike the histogram there is no + /// per-test label to hide behind while the tests run in parallel. The delta is what can be + /// asserted; the absolute value belongs to whatever else ran at the same time. + fn errors_of(kind: &str) -> u64 { + let series = format!("telegram_request_errors_total{{kind=\"{kind}\"}} "); + render_metrics().lines() + .find_map(|line| line.strip_prefix(&series)) + .and_then(|count| count.trim().parse().ok()) + .unwrap_or(0) + } + #[test] fn records_a_failed_request_under_its_own_outcome() { let err = RequestError::Api(ApiError::BotBlocked); + let before = errors_of("api"); let guard = TelegramObserver.on_request("SendDice", RequestBody::Json(b"{}")); guard.on_response(Duration::from_millis(50), Err(&err)); assert_samples("SendDice", "api", 1); + // The same classification feeds both, which is the point of counting the errors here: the + // schedulers never reach a dispatcher, so nothing else would count theirs. + assert!(errors_of("api") > before, "the failed request wasn't counted as an error"); + } + + /// A request that went through must leave the error counter alone, or every graph of the error + /// rate would follow the traffic instead of the failures. + #[test] + fn a_successful_request_is_not_counted_as_an_error() { + let before = errors_of("network"); + + let guard = TelegramObserver.on_request("GetChat", RequestBody::Json(b"{}")); + guard.on_response(Duration::from_millis(10), Ok(())); + + assert_samples("GetChat", "ok", 1); + assert_eq!(errors_of("network"), before); } /// A multipart request has no body to log, but it must still be measured.