feat: add configurable logging level for backend and Mini App

- Introduced a new `LOG_LEVEL` configuration option in the `.env.example` file to allow users to set the logging level (DEBUG, INFO, WARNING, ERROR).
- Updated the `Settings` class to include the `log_level` attribute, normalizing its value to ensure valid logging levels are used.
- Modified the logging setup in `run.py` to utilize the configured log level, enhancing flexibility in log management.
- Enhanced the Mini App to include the logging level in the JavaScript configuration, allowing for consistent logging behavior across the application.
- Added a new `logger.js` module for frontend logging, implementing level-based filtering and console delegation.
- Included unit tests for the new logger functionality to ensure proper behavior and level handling.
This commit is contained in:
2026-03-02 23:15:22 +03:00
parent 67ba9826c7
commit 43386b15fa
16 changed files with 226 additions and 15 deletions

View File

@@ -26,6 +26,9 @@ ADMIN_USERNAMES=admin1,admin2
# When the pinned duty message is updated on schedule, re-pin so members get a notification (default: 1). Set to 0 or false to disable. # When the pinned duty message is updated on schedule, re-pin so members get a notification (default: 1). Set to 0 or false to disable.
# DUTY_PIN_NOTIFY=1 # DUTY_PIN_NOTIFY=1
# Log level for backend and Mini App console logs: DEBUG, INFO, WARNING, ERROR. Default: INFO.
# LOG_LEVEL=INFO
# Single source of language for bot, API, and Mini App (en or ru). Default: en. No auto-detection. # Single source of language for bot, API, and Mini App (en or ru). Default: en. No auto-detection.
# DEFAULT_LANGUAGE=en # DEFAULT_LANGUAGE=en

View File

@@ -20,6 +20,7 @@ All configuration is read from the environment (e.g. `.env` via python-dotenv).
| **DUTY_DISPLAY_TZ** | string (timezone name) | `Europe/Moscow` | Timezone for the pinned duty message in groups. Example: `Europe/Moscow`, `UTC`. | | **DUTY_DISPLAY_TZ** | string (timezone name) | `Europe/Moscow` | Timezone for the pinned duty message in groups. Example: `Europe/Moscow`, `UTC`. |
| **DUTY_PIN_NOTIFY** | `0`, `false`, or `no` to disable | `1` (enabled) | When the pinned duty message is updated on schedule, the bot sends a new message, unpins the old one and pins the new one. If enabled, pinning the new message sends a Telegram notification (“Bot pinned a message”). Set to `0`, `false`, or `no` to pin without notification. The first pin (e.g. when the bot is added to the group or on `/pin_duty`) is always silent. | | **DUTY_PIN_NOTIFY** | `0`, `false`, or `no` to disable | `1` (enabled) | When the pinned duty message is updated on schedule, the bot sends a new message, unpins the old one and pins the new one. If enabled, pinning the new message sends a Telegram notification (“Bot pinned a message”). Set to `0`, `false`, or `no` to pin without notification. The first pin (e.g. when the bot is added to the group or on `/pin_duty`) is always silent. |
| **DEFAULT_LANGUAGE** | `en` or `ru` (normalized) | `en` | **Single source of language for the whole deployment:** bot messages, API error texts, and Mini App UI all use this value. No auto-detection from Telegram user, browser, or `Accept-Language`. Values starting with `ru` are normalized to `ru`; anything else becomes `en`. | | **DEFAULT_LANGUAGE** | `en` or `ru` (normalized) | `en` | **Single source of language for the whole deployment:** bot messages, API error texts, and Mini App UI all use this value. No auto-detection from Telegram user, browser, or `Accept-Language`. Values starting with `ru` are normalized to `ru`; anything else becomes `en`. |
| **LOG_LEVEL** | `DEBUG`, `INFO`, `WARNING`, or `ERROR` | `INFO` | Logging level for the backend (Python `logging`) and for the Mini App console logger (`window.__DT_LOG_LEVEL`). Use `DEBUG` for troubleshooting; in production `INFO` or higher is recommended. |
## Roles and access ## Roles and access

View File

@@ -93,7 +93,11 @@ class NoCacheStaticMiddleware:
headers[idx] = (b"vary", existing + b", " + vary_val) headers[idx] = (b"vary", existing + b", " + vary_val)
else: else:
headers.append((b"vary", vary_val)) headers.append((b"vary", vary_val))
message = {"type": "http.response.start", "status": message["status"], "headers": headers} message = {
"type": "http.response.start",
"status": message["status"],
"headers": headers,
}
await send(message) await send(message)
await self.app(scope, receive, send_wrapper) await self.app(scope, receive, send_wrapper)
@@ -104,13 +108,16 @@ app.add_middleware(NoCacheStaticMiddleware)
@app.get( @app.get(
"/app/config.js", "/app/config.js",
summary="Mini App config (language)", summary="Mini App config (language, log level)",
description="Returns JS that sets window.__DT_LANG from DEFAULT_LANGUAGE. Loaded before main.js.", description=(
"Returns JS that sets window.__DT_LANG and window.__DT_LOG_LEVEL. Loaded before main.js."
),
) )
def app_config_js() -> Response: def app_config_js() -> Response:
"""Return JS assigning window.__DT_LANG for the webapp. No caching.""" """Return JS assigning window.__DT_LANG and window.__DT_LOG_LEVEL for the webapp. No caching."""
lang = config.DEFAULT_LANGUAGE lang = config.DEFAULT_LANGUAGE
body = f'window.__DT_LANG = "{lang}";' log_level = config.LOG_LEVEL_STR.lower()
body = f'window.__DT_LANG = "{lang}";\nwindow.__DT_LOG_LEVEL = "{log_level}";'
return Response( return Response(
content=body, content=body,
media_type="application/javascript; charset=utf-8", media_type="application/javascript; charset=utf-8",

View File

@@ -20,6 +20,7 @@ from duty_teller.utils.dates import DateRangeValidationError, validate_date_rang
log = logging.getLogger(__name__) log = logging.getLogger(__name__)
def _lang_from_accept_language(header: str | None) -> str: def _lang_from_accept_language(header: str | None) -> str:
"""Return the application language: always config.DEFAULT_LANGUAGE. """Return the application language: always config.DEFAULT_LANGUAGE.

View File

@@ -4,6 +4,7 @@ BOT_TOKEN is not validated on import; call require_bot_token() in the entry poin
when running the bot. when running the bot.
""" """
import logging
import os import os
import re import re
from dataclasses import dataclass from dataclasses import dataclass
@@ -46,6 +47,14 @@ def _parse_phone_list(raw: str) -> set[str]:
return result return result
def _normalize_log_level(raw: str) -> str:
"""Return a valid log level name (DEBUG, INFO, WARNING, ERROR); default INFO."""
level = (raw or "").strip().upper()
if level in ("DEBUG", "INFO", "WARNING", "ERROR"):
return level
return "INFO"
@dataclass(frozen=True) @dataclass(frozen=True)
class Settings: class Settings:
"""Injectable settings built from environment. Used in tests or when env is overridden.""" """Injectable settings built from environment. Used in tests or when env is overridden."""
@@ -67,6 +76,7 @@ class Settings:
duty_display_tz: str duty_display_tz: str
default_language: str default_language: str
duty_pin_notify: bool duty_pin_notify: bool
log_level: str
@classmethod @classmethod
def from_env(cls) -> "Settings": def from_env(cls) -> "Settings":
@@ -118,6 +128,7 @@ class Settings:
default_language=normalize_lang(os.getenv("DEFAULT_LANGUAGE", "en")), default_language=normalize_lang(os.getenv("DEFAULT_LANGUAGE", "en")),
duty_pin_notify=os.getenv("DUTY_PIN_NOTIFY", "1").strip().lower() duty_pin_notify=os.getenv("DUTY_PIN_NOTIFY", "1").strip().lower()
not in ("0", "false", "no"), not in ("0", "false", "no"),
log_level=_normalize_log_level(os.getenv("LOG_LEVEL", "INFO")),
) )
@@ -141,6 +152,8 @@ EXTERNAL_CALENDAR_ICS_URL = _settings.external_calendar_ics_url
DUTY_DISPLAY_TZ = _settings.duty_display_tz DUTY_DISPLAY_TZ = _settings.duty_display_tz
DEFAULT_LANGUAGE = _settings.default_language DEFAULT_LANGUAGE = _settings.default_language
DUTY_PIN_NOTIFY = _settings.duty_pin_notify DUTY_PIN_NOTIFY = _settings.duty_pin_notify
LOG_LEVEL = getattr(logging, _settings.log_level.upper(), logging.INFO)
LOG_LEVEL_STR = _settings.log_level
def is_admin(username: str) -> bool: def is_admin(username: str) -> bool:

View File

@@ -24,7 +24,7 @@ async def _resolve_bot_username(application) -> None:
logging.basicConfig( logging.basicConfig(
format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
level=logging.INFO, level=config.LOG_LEVEL,
) )
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)

View File

@@ -17,7 +17,9 @@ class TestLangFromAcceptLanguage:
assert deps._lang_from_accept_language(None) == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language(None) == config.DEFAULT_LANGUAGE
assert deps._lang_from_accept_language("") == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language("") == config.DEFAULT_LANGUAGE
assert deps._lang_from_accept_language(" ") == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language(" ") == config.DEFAULT_LANGUAGE
assert deps._lang_from_accept_language("ru-RU,ru;q=0.9") == config.DEFAULT_LANGUAGE assert (
deps._lang_from_accept_language("ru-RU,ru;q=0.9") == config.DEFAULT_LANGUAGE
)
assert deps._lang_from_accept_language("en-US") == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language("en-US") == config.DEFAULT_LANGUAGE
assert deps._lang_from_accept_language("zz") == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language("zz") == config.DEFAULT_LANGUAGE
assert deps._lang_from_accept_language("x") == config.DEFAULT_LANGUAGE assert deps._lang_from_accept_language("x") == config.DEFAULT_LANGUAGE

View File

@@ -35,7 +35,9 @@ def test_app_static_has_no_store_and_vary(client):
r = client.get("/app/") r = client.get("/app/")
if r.status_code != 200: if r.status_code != 200:
r = client.get("/app") r = client.get("/app")
assert r.status_code == 200, "webapp static mount should serve index at /app or /app/" assert r.status_code == 200, (
"webapp static mount should serve index at /app or /app/"
)
assert r.headers.get("cache-control") == "no-store" assert r.headers.get("cache-control") == "no-store"
assert "accept-language" in r.headers.get("vary", "").lower() assert "accept-language" in r.headers.get("vary", "").lower()

View File

@@ -86,11 +86,6 @@
padding-bottom: 12px; padding-bottom: 12px;
margin-bottom: 4px; margin-bottom: 4px;
touch-action: pan-y; touch-action: pan-y;
transition: box-shadow var(--transition-fast) ease-out;
}
.calendar-sticky.is-scrolled {
box-shadow: 0 2px 8px rgba(0, 0, 0, 0.15);
} }
.calendar { .calendar {

View File

@@ -58,6 +58,7 @@
"./js/dutyList.js": "./js/dutyList.js?v=2", "./js/dutyList.js": "./js/dutyList.js?v=2",
"./js/hints.js": "./js/hints.js?v=2", "./js/hints.js": "./js/hints.js?v=2",
"./js/i18n.js": "./js/i18n.js?v=3", "./js/i18n.js": "./js/i18n.js?v=3",
"./js/logger.js": "./js/logger.js?v=1",
"./js/theme.js": "./js/theme.js?v=2", "./js/theme.js": "./js/theme.js?v=2",
"./js/ui.js": "./js/ui.js?v=2", "./js/ui.js": "./js/ui.js?v=2",
"./js/utils.js": "./js/utils.js?v=2" "./js/utils.js": "./js/utils.js?v=2"

View File

@@ -6,6 +6,7 @@ import { FETCH_TIMEOUT_MS } from "./constants.js";
import { getInitData } from "./auth.js"; import { getInitData } from "./auth.js";
import { state } from "./dom.js"; import { state } from "./dom.js";
import { t } from "./i18n.js"; import { t } from "./i18n.js";
import { logger } from "./logger.js";
/** /**
* Build fetch options with init data header, Accept-Language and timeout abort. * Build fetch options with init data header, Accept-Language and timeout abort.
@@ -49,10 +50,17 @@ export async function apiGet(path, params = {}, options = {}) {
const query = new URLSearchParams(params).toString(); const query = new URLSearchParams(params).toString();
const url = query ? `${base}${path}?${query}` : `${base}${path}`; const url = query ? `${base}${path}?${query}` : `${base}${path}`;
const initData = getInitData(); const initData = getInitData();
logger.debug("API request", path, params);
const opts = buildFetchOptions(initData, options.signal); const opts = buildFetchOptions(initData, options.signal);
try { try {
const res = await fetch(url, { headers: opts.headers, signal: opts.signal }); const res = await fetch(url, { headers: opts.headers, signal: opts.signal });
if (!res.ok) {
logger.warn("API non-OK response", path, res.status);
}
return res; return res;
} catch (e) {
logger.error("API request failed", path, e);
throw e;
} finally { } finally {
opts.cleanup(); opts.cleanup();
} }
@@ -69,6 +77,7 @@ export async function apiGet(path, params = {}, options = {}) {
export async function fetchDuties(from, to, signal) { export async function fetchDuties(from, to, signal) {
const res = await apiGet("/api/duties", { from, to }, { signal }); const res = await apiGet("/api/duties", { from, to }, { signal });
if (res.status === 403) { if (res.status === 403) {
logger.warn("Access denied", from, to);
let detail = t(state.lang, "access_denied"); let detail = t(state.lang, "access_denied");
try { try {
const body = await res.json(); const body = await res.json();

View File

@@ -2,6 +2,8 @@
* Telegram init data and access checks. * Telegram init data and access checks.
*/ */
import { logger } from "./logger.js";
/** /**
* Get tgWebAppData value from hash when it contains unencoded & and =. * Get tgWebAppData value from hash when it contains unencoded & and =.
* Value runs from tgWebAppData= until next &tgWebApp or end. * Value runs from tgWebAppData= until next &tgWebApp or end.
@@ -33,7 +35,10 @@ export function getInitData() {
const hash = window.location.hash ? window.location.hash.slice(1) : ""; const hash = window.location.hash ? window.location.hash.slice(1) : "";
if (hash) { if (hash) {
const fromHash = getTgWebAppDataFromHash(hash); const fromHash = getTgWebAppDataFromHash(hash);
if (fromHash) return fromHash; if (fromHash) {
logger.debug("initData from hash");
return fromHash;
}
const hashParams = new URLSearchParams(hash); const hashParams = new URLSearchParams(hash);
const tgFromHash = hashParams.get("tgWebAppData"); const tgFromHash = hashParams.get("tgWebAppData");
if (tgFromHash) return tgFromHash; if (tgFromHash) return tgFromHash;
@@ -42,6 +47,7 @@ export function getInitData() {
? new URLSearchParams(window.location.search).get("tgWebAppData") ? new URLSearchParams(window.location.search).get("tgWebAppData")
: null; : null;
if (q) { if (q) {
logger.debug("initData from query");
return q; return q;
} }
return ""; return "";

View File

@@ -110,7 +110,7 @@ export const MESSAGES = {
"contact.back": "Назад", "contact.back": "Назад",
"contact.phone": "Телефон", "contact.phone": "Телефон",
"contact.telegram": "Telegram", "contact.telegram": "Telegram",
"current_duty.title": "Текущее дежурство", "current_duty.title": "Сейчас дежурит",
"current_duty.no_duty": "Сейчас никто не дежурит", "current_duty.no_duty": "Сейчас никто не дежурит",
"current_duty.shift": "Смена", "current_duty.shift": "Смена",
"current_duty.remaining": "Осталось: {hours}ч {minutes}мин", "current_duty.remaining": "Осталось: {hours}ч {minutes}мин",

71
webapp/js/logger.js Normal file
View File

@@ -0,0 +1,71 @@
/**
* Frontend logger with configurable level (window.__DT_LOG_LEVEL).
* Only messages at or above the configured level are forwarded to console.
* Prefix [DutyTeller][level] for DevTools filtering.
*/
const LEVEL_ORDER = { debug: 0, info: 1, warn: 2, error: 3 };
/**
* Resolve current log level from window.__DT_LOG_LEVEL. Default: info.
* @returns {string} One of "debug", "info", "warn", "error"
*/
function getLogLevel() {
const raw =
(typeof window !== "undefined" && window.__DT_LOG_LEVEL) || "info";
const level = String(raw).toLowerCase();
return LEVEL_ORDER.hasOwnProperty(level) ? level : "info";
}
/**
* Return true if message at level should be emitted (level >= configured).
* @param {string} messageLevel - "debug" | "info" | "warn" | "error"
* @returns {boolean}
*/
function shouldLog(messageLevel) {
const configured = getLogLevel();
const configuredNum = LEVEL_ORDER[configured] ?? 1;
const messageNum = LEVEL_ORDER[messageLevel] ?? 1;
return messageNum >= configuredNum;
}
const PREFIX = "[DutyTeller]";
function logAt(level, args) {
if (!shouldLog(level)) return;
const consoleMethod =
level === "debug"
? console.debug
: level === "info"
? console.info
: level === "warn"
? console.warn
: console.error;
const prefix = `${PREFIX}[${level}]`;
if (args.length === 0) {
consoleMethod(prefix);
} else if (args.length === 1) {
consoleMethod(prefix, args[0]);
} else {
consoleMethod(prefix, ...args);
}
}
/**
* Logger object with debug, info, warn, error (signature like console).
* Example: logger.info("Loaded", { count: 5 });
*/
export const logger = {
debug(msg, ...args) {
logAt("debug", [msg, ...args]);
},
info(msg, ...args) {
logAt("info", [msg, ...args]);
},
warn(msg, ...args) {
logAt("warn", [msg, ...args]);
},
error(msg, ...args) {
logAt("error", [msg, ...args]);
},
};

94
webapp/js/logger.test.js Normal file
View File

@@ -0,0 +1,94 @@
/**
* Unit tests for logger: level filtering and console delegation.
*/
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
import { logger } from "./logger.js";
describe("logger", () => {
const origWindow = globalThis.window;
beforeEach(() => {
vi.spyOn(console, "debug").mockImplementation(() => {});
vi.spyOn(console, "info").mockImplementation(() => {});
vi.spyOn(console, "warn").mockImplementation(() => {});
vi.spyOn(console, "error").mockImplementation(() => {});
});
afterEach(() => {
vi.restoreAllMocks();
if (globalThis.window) {
delete globalThis.window.__DT_LOG_LEVEL;
}
});
function setLevel(level) {
if (!globalThis.window) globalThis.window = {};
globalThis.window.__DT_LOG_LEVEL = level;
}
it("at level info does not call console.debug", () => {
setLevel("info");
logger.debug("test");
expect(console.debug).not.toHaveBeenCalled();
});
it("at level info calls console.info for logger.info", () => {
setLevel("info");
logger.info("hello");
expect(console.info).toHaveBeenCalledWith("[DutyTeller][info]", "hello");
});
it("at level info calls console.warn and console.error", () => {
setLevel("info");
logger.warn("w");
logger.error("e");
expect(console.warn).toHaveBeenCalledWith("[DutyTeller][warn]", "w");
expect(console.error).toHaveBeenCalledWith("[DutyTeller][error]", "e");
});
it("at level debug calls console.debug", () => {
setLevel("debug");
logger.debug("dbg");
expect(console.debug).toHaveBeenCalledWith("[DutyTeller][debug]", "dbg");
});
it("at level error does not call console.debug or console.info", () => {
setLevel("error");
logger.debug("d");
logger.info("i");
expect(console.debug).not.toHaveBeenCalled();
expect(console.info).not.toHaveBeenCalled();
});
it("at level error calls console.error", () => {
setLevel("error");
logger.error("err");
expect(console.error).toHaveBeenCalledWith("[DutyTeller][error]", "err");
});
it("passes extra args to console", () => {
setLevel("info");
logger.info("msg", { foo: 1 }, "bar");
expect(console.info).toHaveBeenCalledWith(
"[DutyTeller][info]",
"msg",
{ foo: 1 },
"bar"
);
});
it("defaults to info when __DT_LOG_LEVEL is missing", () => {
if (globalThis.window) delete globalThis.window.__DT_LOG_LEVEL;
logger.debug("no");
expect(console.debug).not.toHaveBeenCalled();
logger.info("yes");
expect(console.info).toHaveBeenCalledWith("[DutyTeller][info]", "yes");
});
it("defaults to info when __DT_LOG_LEVEL is invalid", () => {
setLevel("invalid");
logger.debug("no");
expect(console.debug).not.toHaveBeenCalled();
});
});

View File

@@ -17,6 +17,7 @@ import {
} from "./dom.js"; } from "./dom.js";
import { showAccessDenied, hideAccessDenied, showError, setNavEnabled } from "./ui.js"; import { showAccessDenied, hideAccessDenied, showError, setNavEnabled } from "./ui.js";
import { fetchDuties, fetchCalendarEvents } from "./api.js"; import { fetchDuties, fetchCalendarEvents } from "./api.js";
import { logger } from "./logger.js";
import { import {
dutiesByDate, dutiesByDate,
calendarEventsByDate, calendarEventsByDate,
@@ -65,6 +66,8 @@ export function applyLangToUi() {
applyLangToUi(); applyLangToUi();
logger.info("App init", "lang=" + state.lang);
window.__dtReady = true; window.__dtReady = true;
/** /**
@@ -148,6 +151,7 @@ async function loadMonth() {
const from = localDateString(start); const from = localDateString(start);
const to = localDateString(gridEnd); const to = localDateString(gridEnd);
try { try {
logger.debug("Loading month", from, to);
const dutiesPromise = fetchDuties(from, to, signal); const dutiesPromise = fetchDuties(from, to, signal);
const eventsPromise = fetchCalendarEvents(from, to, signal); const eventsPromise = fetchCalendarEvents(from, to, signal);
const duties = await dutiesPromise; const duties = await dutiesPromise;
@@ -186,6 +190,7 @@ async function loadMonth() {
return; return;
} }
if (e.message === "ACCESS_DENIED") { if (e.message === "ACCESS_DENIED") {
logger.warn("Access denied in loadMonth", e.serverDetail);
showAccessDenied(e.serverDetail); showAccessDenied(e.serverDetail);
setNavEnabled(true); setNavEnabled(true);
if ( if (
@@ -198,6 +203,7 @@ async function loadMonth() {
} }
return; return;
} }
logger.error("Load month failed", e);
showError(e.message || t(state.lang, "error_generic"), loadMonth); showError(e.message || t(state.lang, "error_generic"), loadMonth);
setNavEnabled(true); setNavEnabled(true);
return; return;