Vito
65b15bbe75
* fix(logs): Clear all logs deletes and empties only what its confirmation showed (#389) - /logs/files rows carry an identity string (size:mtime_ns:ino); the workspace sends back the active and rotated rows its dialog was built from. Under the files and handler locks every listed copy is re-checked with _matches_review and the listed active log's inode; any difference refuses with nothing changed (409 logs-changed). A copy that appeared after the confirmation is kept. - A second writer of the active log (our flushed stream is behind the file's size, or our file is now a rotated copy) refuses first (409 logs-foreign-writer); each unlink is preceded by a fresh identity check and the active log is emptied last. - An active log with a hard link (st_nlink > 1) is never truncated (409 logs-hard-link), also on the file-logging-off path. - The legacy admin page's POST without a body keeps clearing what is there, with the foreign-writer and hard-link refusals. - The browser fixture grows the active log through the handler's stream. * fix(logs): accept pre-1970 identities, refuse duplicate rows, say the foreign-writer check is best effort (#389) Review follow-ups: a negative mtime_ns no longer makes every workspace clear 400; a name listed twice is a malformed list; the confirmed-row cap is 10000; the hard-link refusal says how to recover; the hard-link and foreign-append tests assert the kept bytes before the refusal code, so on the old code they fail on lost data.
294 lines
12 KiB
Python
294 lines
12 KiB
Python
"""System › Diagnostics & logs test hooks for the browser tests (#249 System S12).
|
||
|
||
The logger writes into ``<server root>/logs`` (``repoint_logs``, called by
|
||
``create_app`` before any record is written), so no test reads or deletes a
|
||
real log folder. Every route refuses a log folder outside the server root.
|
||
|
||
- ``POST /__test__/logs/reset`` restores the default logging configuration,
|
||
empties the active log, removes every other entry of the log folder (a
|
||
link is removed, never followed) and clears the in-memory buffer. The
|
||
global ``/__test__/reset`` calls it too;
|
||
- ``POST /__test__/logs/seed`` ``{records, filler, rotated, active, link,
|
||
other}`` writes buffer records with fixed times (``records``: the concept's
|
||
four lines, then one DEBUG, ERROR and CRITICAL record, older; ``filler``
|
||
more INFO records older still), ``active`` bytes into the active log,
|
||
rotated copies ``prompt_manager.log.<n>`` of the listed sizes (fixed
|
||
times), on POSIX a symlink ``prompt_manager.log.<n+1>`` to a file outside
|
||
the folder (``link``) and a user's ``prompt_manager.log.bak`` (``other``).
|
||
``{mode: "concept"}`` reproduces the concept's Logs sample (app.js 695)
|
||
for the comparison: the buffer holds only its four lines, the active log
|
||
is 1.4 MB with three rotated copies ("prompt_manager.log · 1.4 MB · rotated
|
||
copies: 3") and console logging is off, as the concept's toggle;
|
||
- ``POST /__test__/logs/rotate`` rolls the copies over as the handler does
|
||
(``.2`` → ``.3``, ``.1`` → ``.2``, a new ``.1``), so a reviewed plan no
|
||
longer matches;
|
||
- ``GET /__test__/logs/state`` answers the folder's entries (name, size, link)
|
||
and the buffer's length.
|
||
"""
|
||
|
||
import datetime
|
||
import logging
|
||
import os
|
||
import shutil
|
||
from pathlib import Path
|
||
|
||
from aiohttp import web
|
||
|
||
ACTIVE = "prompt_manager.log"
|
||
SEED_DAY = datetime.datetime(2026, 10, 26)
|
||
# The concept's four lines (app.js 695), oldest first: the viewer shows them
|
||
# newest first.
|
||
CONCEPT_RECORDS = (
|
||
("09:38:52", logging.INFO, "Source monitor started: output"),
|
||
("09:39:04", logging.INFO, "Database backup verified"),
|
||
("09:42:18", logging.WARNING, "3 images have ambiguous prompt metadata"),
|
||
("09:42:18", logging.INFO, "Scan completed: 12 enriched, 0 duplicate links"),
|
||
)
|
||
# Older than the concept's lines, so they come after them: the levels the
|
||
# concept does not show.
|
||
LEVEL_RECORDS = (
|
||
("09:30:01", logging.DEBUG, "Thumbnail cache lookup"),
|
||
("09:30:02", logging.ERROR, "A source folder could not be read"),
|
||
("09:30:03", logging.CRITICAL, "The database could not be opened"),
|
||
)
|
||
ROTATED_TIME = datetime.datetime(2026, 10, 25, 14, 2)
|
||
# The concept's "prompt_manager.log · 1.4 MB · rotated copies: 3": the active
|
||
# log stays under 1.45 MB while the server writes its own lines.
|
||
CONCEPT_ACTIVE = int(1.4 * 1024 * 1024)
|
||
CONCEPT_ROTATED = (3072, 2048, 1024)
|
||
MAX_SEED_BYTES = 64 * 1024 * 1024
|
||
DEFAULT_CONFIG = {
|
||
"level": "INFO",
|
||
"max_file_size": 10 * 1024 * 1024,
|
||
"backup_count": 5,
|
||
"console_logging": True,
|
||
"file_logging": True,
|
||
"buffer_size": 1000,
|
||
}
|
||
|
||
|
||
def _manager():
|
||
from utils.logging_config import get_logger_manager
|
||
|
||
return get_logger_manager()
|
||
|
||
|
||
def repoint_logs(root: Path) -> Path:
|
||
"""Point the logger at ``<root>/logs`` before anything is logged.
|
||
|
||
The logger is built while ``logs_dir`` answers that folder, so its first
|
||
handler never opens a log file anywhere else (a node folder with a legacy
|
||
database would otherwise name a real log folder).
|
||
"""
|
||
from utils import library_location
|
||
|
||
folder = Path(root) / "logs"
|
||
folder.mkdir(exist_ok=True)
|
||
original = library_location.logs_dir
|
||
library_location.logs_dir = lambda **_kwargs: str(folder)
|
||
try:
|
||
manager = _manager()
|
||
finally:
|
||
library_location.logs_dir = original
|
||
with manager._files_lock:
|
||
manager.log_dir = folder
|
||
manager._setup_loggers()
|
||
return folder
|
||
|
||
|
||
def _require_inside(root: Path, folder: Path) -> None:
|
||
resolved = Path(os.path.realpath(folder))
|
||
if Path(os.path.realpath(root)) not in resolved.parents:
|
||
raise web.HTTPForbidden(text="The log folder is outside the test server root")
|
||
|
||
|
||
def _record(time_text, level, message, index):
|
||
record = logging.LogRecord(
|
||
"prompt_manager.test", level, __file__, index, message, None, None
|
||
)
|
||
hours, minutes, seconds = (int(part) for part in time_text.split(":"))
|
||
moment = SEED_DAY.replace(hour=hours, minute=minutes, second=seconds)
|
||
# Equal times keep their order: each later record is a microsecond newer.
|
||
record.created = moment.timestamp() + index / 1e6
|
||
return record
|
||
|
||
|
||
def _touch(path: Path, size: int, moment: datetime.datetime) -> None:
|
||
# A link at this name is replaced, never written through.
|
||
if path.is_symlink():
|
||
path.unlink()
|
||
with open(path, "wb") as handle:
|
||
handle.write(b"x" * size)
|
||
stamp = moment.timestamp()
|
||
os.utime(path, (stamp, stamp))
|
||
|
||
|
||
def _append_active(manager, log_dir: Path, size: int) -> None:
|
||
"""Grow the active log as this process's handler does (#389).
|
||
|
||
A second handle appending to the file the handler writes is what Clear
|
||
all logs refuses as another program writing to it, so the bytes go
|
||
through the handler's own stream; with file logging off, to the file.
|
||
"""
|
||
|
||
def same(path) -> bool:
|
||
return os.path.normcase(os.path.realpath(path)) == os.path.normcase(
|
||
os.path.realpath(log_dir / ACTIVE)
|
||
)
|
||
|
||
for handler in manager._file_handlers():
|
||
stream = getattr(handler, "stream", None)
|
||
if stream is None or not same(handler.baseFilename):
|
||
continue
|
||
handler.acquire()
|
||
try:
|
||
stream.write("x" * size)
|
||
stream.flush()
|
||
finally:
|
||
handler.release()
|
||
return
|
||
with open(log_dir / ACTIVE, "ab") as handle:
|
||
handle.write(b"x" * size)
|
||
|
||
|
||
def _bounded(value, name, top=MAX_SEED_BYTES):
|
||
if isinstance(value, bool) or not isinstance(value, int) or not 0 <= value <= top:
|
||
raise web.HTTPBadRequest(text=f"{name} must be an integer 0..{top}")
|
||
return value
|
||
|
||
|
||
def register_diagnostics_commands(app, routes, api, root: Path):
|
||
"""Register the hooks; returns ``reset()`` for the global reset."""
|
||
|
||
def folder() -> Path:
|
||
path = Path(_manager().log_dir)
|
||
_require_inside(root, path)
|
||
return path
|
||
|
||
def reset() -> None:
|
||
manager = _manager()
|
||
log_dir = folder()
|
||
if manager.get_config() != DEFAULT_CONFIG:
|
||
manager.update_config(dict(DEFAULT_CONFIG))
|
||
with manager._files_lock:
|
||
held = manager._acquire_file_handlers()
|
||
try:
|
||
with os.scandir(log_dir) as entries:
|
||
found = list(entries)
|
||
for entry in found:
|
||
path = Path(entry.path)
|
||
if entry.name == ACTIVE and entry.is_file(follow_symlinks=False):
|
||
manager._truncate_main_log(path)
|
||
elif entry.is_dir(follow_symlinks=False):
|
||
shutil.rmtree(path)
|
||
else:
|
||
os.unlink(path)
|
||
finally:
|
||
manager._release_handlers(held)
|
||
with manager._buffer_lock:
|
||
manager._log_buffer.clear()
|
||
|
||
def seed_concept() -> None:
|
||
manager = _manager()
|
||
log_dir = folder()
|
||
manager.update_config({"console_logging": False})
|
||
with manager._buffer_lock:
|
||
manager._log_buffer.clear()
|
||
for index, (time_text, level, message) in enumerate(CONCEPT_RECORDS):
|
||
record = _record(time_text, level, message, index)
|
||
manager.add_to_buffer(record, record.getMessage())
|
||
_append_active(manager, log_dir, CONCEPT_ACTIVE)
|
||
for number, size in enumerate(CONCEPT_ROTATED, start=1):
|
||
moment = ROTATED_TIME - datetime.timedelta(hours=number)
|
||
_touch(log_dir / f"{ACTIVE}.{number}", size, moment)
|
||
|
||
def seed(data) -> None:
|
||
if data.get("mode") == "concept":
|
||
seed_concept()
|
||
return
|
||
manager = _manager()
|
||
log_dir = folder()
|
||
with_records = data.get("records", True) is not False
|
||
filler = _bounded(data.get("filler", 0), "filler", 900)
|
||
older = [
|
||
(f"08:{index // 60:02}:{index % 60:02}", logging.INFO, f"Filler {index}")
|
||
for index in range(filler)
|
||
]
|
||
named = list(LEVEL_RECORDS) + list(CONCEPT_RECORDS) if with_records else []
|
||
ordered = older + named
|
||
for index, (time_text, level, message) in enumerate(ordered):
|
||
record = _record(time_text, level, message, index)
|
||
manager.add_to_buffer(record, record.getMessage())
|
||
active = _bounded(data.get("active", 0), "active")
|
||
if active:
|
||
_append_active(manager, log_dir, active)
|
||
rotated = data.get("rotated", [])
|
||
if not isinstance(rotated, list) or len(rotated) > 20:
|
||
raise web.HTTPBadRequest(text="rotated must be a list of sizes")
|
||
for number, size in enumerate(rotated, start=1):
|
||
moment = ROTATED_TIME - datetime.timedelta(hours=number)
|
||
_touch(log_dir / f"{ACTIVE}.{number}", _bounded(size, "size"), moment)
|
||
if data.get("link") and os.name != "nt":
|
||
target = Path(root) / "outside-log-target.txt"
|
||
target.write_bytes(b"not a log of this folder")
|
||
os.symlink(target, log_dir / f"{ACTIVE}.{len(rotated) + 1}")
|
||
if data.get("other"):
|
||
_touch(log_dir / f"{ACTIVE}.bak", 0, ROTATED_TIME)
|
||
|
||
def rotate() -> None:
|
||
manager = _manager()
|
||
log_dir = folder()
|
||
with manager._files_lock:
|
||
held = manager._acquire_file_handlers()
|
||
try:
|
||
for number in (2, 1):
|
||
source = log_dir / f"{ACTIVE}.{number}"
|
||
if source.is_file() and not source.is_symlink():
|
||
os.replace(source, log_dir / f"{ACTIVE}.{number + 1}")
|
||
_touch(log_dir / f"{ACTIVE}.1", 4096, datetime.datetime.now())
|
||
finally:
|
||
manager._release_handlers(held)
|
||
|
||
def state():
|
||
manager = _manager()
|
||
log_dir = folder()
|
||
entries = []
|
||
with os.scandir(log_dir) as listing:
|
||
found = sorted(listing, key=lambda item: item.name)
|
||
for entry in found:
|
||
info = entry.stat(follow_symlinks=False)
|
||
entries.append(
|
||
{"name": entry.name, "size": info.st_size, "link": entry.is_symlink()}
|
||
)
|
||
with manager._buffer_lock:
|
||
buffered = len(manager._log_buffer)
|
||
return {"entries": entries, "buffer": buffered, "config": manager.get_config()}
|
||
|
||
async def body(request):
|
||
data = await request.json() if request.can_read_body else {}
|
||
if not isinstance(data, dict):
|
||
raise web.HTTPBadRequest()
|
||
return data
|
||
|
||
@routes.post("/__test__/logs/reset")
|
||
async def logs_reset(request: web.Request) -> web.Response:
|
||
await api._run_in_executor(reset)
|
||
return web.json_response({"success": True})
|
||
|
||
@routes.post("/__test__/logs/seed")
|
||
async def logs_seed(request: web.Request) -> web.Response:
|
||
data = await body(request)
|
||
await api._run_in_executor(seed, data)
|
||
return web.json_response({"success": True})
|
||
|
||
@routes.post("/__test__/logs/rotate")
|
||
async def logs_rotate(request: web.Request) -> web.Response:
|
||
await api._run_in_executor(rotate)
|
||
return web.json_response({"success": True})
|
||
|
||
@routes.get("/__test__/logs/state")
|
||
async def logs_state(request: web.Request) -> web.Response:
|
||
return web.json_response(await api._run_in_executor(state))
|
||
|
||
return reset
|