feat(syslog): a syslog receiver: UDP and TCP, senders offered before they're kept, each source's lines in a ring (#5999)
- plugins/syslog: RFC 5424 and RFC 3164 parsing, RFC 6587 TCP framing. - Lines are queued as they arrive and stored every 5 s through a Holding, so a storage stall delays them rather than losing them. - A new sender is an offered source, counted and not kept, until an admin adds it on the Syslog page (name, host); it can be ignored instead. - The listener follows the plugin's settings (port, UDP, TCP), rebinding within seconds of a save; a port it can't open is said on the page. - Hourly ring per source: age window and byte cap from Settings. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
@@ -0,0 +1,100 @@
|
||||
"""Integration: syslog lines stored against Postgres (#5999). A new sender is
|
||||
offered and its lines counted, not kept; an added source's lines are kept;
|
||||
the ring keeps each source within its age window and byte cap."""
|
||||
from __future__ import annotations
|
||||
|
||||
import asyncio
|
||||
import os
|
||||
from datetime import datetime, timedelta, timezone
|
||||
|
||||
import pytest
|
||||
|
||||
pytestmark = pytest.mark.integration
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def app():
|
||||
if not os.environ.get("STEWARD_DATABASE_URL"):
|
||||
pytest.skip("needs Postgres")
|
||||
from steward.app import create_app
|
||||
return create_app(testing=False)
|
||||
|
||||
|
||||
def _received(address, text, at):
|
||||
from plugins.syslog.parse import parse
|
||||
from plugins.syslog.receiver import Received
|
||||
return Received(at, address, parse(f"<11>Oct 19 01:12:03 synnas kernel: {text}"))
|
||||
|
||||
|
||||
def test_an_unknown_sender_is_offered_and_an_added_one_kept(app):
|
||||
from sqlalchemy import delete, func, select
|
||||
|
||||
from plugins.syslog.models import SyslogLine, SyslogSource
|
||||
from plugins.syslog.receiver import store_lines
|
||||
|
||||
now = datetime(2026, 10, 19, 3, 0, tzinfo=timezone.utc)
|
||||
|
||||
async def go():
|
||||
async with app.db_sessionmaker() as s:
|
||||
async with s.begin():
|
||||
await s.execute(delete(SyslogSource))
|
||||
await store_lines(s, [_received("10.9.0.1", "first", now),
|
||||
_received("10.9.0.1", "second", now + timedelta(seconds=1))])
|
||||
async with app.db_sessionmaker() as s:
|
||||
src = (await s.execute(select(SyslogSource))).scalar_one()
|
||||
assert (src.state, src.lines_total, src.hostname_seen) == ("offered", 2, "synnas")
|
||||
assert src.last_line == "second" and src.last_severity == 3
|
||||
assert (await s.execute(select(func.count()).select_from(SyslogLine))).scalar_one() == 0
|
||||
src_id = src.id
|
||||
async with app.db_sessionmaker() as s:
|
||||
async with s.begin():
|
||||
(await s.get(SyslogSource, src_id)).state = "accepted"
|
||||
async with app.db_sessionmaker() as s:
|
||||
async with s.begin():
|
||||
await store_lines(s, [_received("10.9.0.1", "kept", now + timedelta(seconds=2))])
|
||||
async with app.db_sessionmaker() as s:
|
||||
lines = (await s.execute(select(SyslogLine))).scalars().all()
|
||||
assert [(l.app, l.hostname, l.message, l.severity) for l in lines] == [("kernel", "synnas", "kept", 3)]
|
||||
assert (await s.get(SyslogSource, src_id)).lines_total == 3
|
||||
async with s.begin():
|
||||
await s.execute(delete(SyslogSource))
|
||||
|
||||
asyncio.run(go())
|
||||
|
||||
|
||||
def test_the_ring_keeps_each_source_within_its_window_and_cap(app):
|
||||
from sqlalchemy import delete, select
|
||||
|
||||
from plugins.syslog.models import SyslogLine, SyslogSource
|
||||
from plugins.syslog.retention import prune_syslog_lines
|
||||
|
||||
now = datetime(2026, 10, 19, 3, 0, tzinfo=timezone.utc)
|
||||
line40 = "x" * 40 # cap 100 keeps 3 (prefixes 0, 40, 80)
|
||||
|
||||
async def go():
|
||||
async with app.db_sessionmaker() as s:
|
||||
async with s.begin():
|
||||
await s.execute(delete(SyslogSource))
|
||||
a = SyslogSource(address="10.9.0.2", state="accepted", first_seen_at=now, last_seen_at=now)
|
||||
b = SyslogSource(address="10.9.0.3", state="accepted", first_seen_at=now, last_seen_at=now)
|
||||
s.add_all([a, b])
|
||||
await s.flush()
|
||||
|
||||
def line(src, minutes_ago, text):
|
||||
return SyslogLine(source_id=src.id, received_at=now - timedelta(minutes=minutes_ago),
|
||||
facility=1, severity=6, message=text)
|
||||
|
||||
s.add(line(a, 60 * 24 * 30, "old"))
|
||||
s.add_all([line(a, 6 - i, line40) for i in range(1, 6)])
|
||||
s.add_all([line(b, 2, line40), line(b, 1, line40)])
|
||||
a_id, b_id = a.id, b.id
|
||||
async with app.db_sessionmaker() as s:
|
||||
async with s.begin():
|
||||
counts = await prune_syslog_lines(s, retention_days=14, max_bytes_per_source=100, now=now)
|
||||
kept = (await s.execute(select(SyslogLine.source_id))).scalars().all()
|
||||
assert counts == {"age_pruned": 1, "size_pruned": 2}
|
||||
assert kept.count(a_id) == 3 and kept.count(b_id) == 2
|
||||
async with s.begin():
|
||||
await s.execute(delete(SyslogSource))
|
||||
|
||||
asyncio.run(go())
|
||||
@@ -0,0 +1,61 @@
|
||||
"""Syslog messages read into their parts (#5999): RFC 5424, RFC 3164 with and
|
||||
without a hostname, a message with no PRI, and TCP framing (RFC 6587)."""
|
||||
from datetime import datetime, timezone
|
||||
|
||||
from plugins.syslog.parse import MAX_MESSAGE, facility_name, frames, parse, severity_name
|
||||
|
||||
|
||||
def test_rfc5424_with_structured_data_and_a_zone():
|
||||
m = parse(b'<165>1 2026-10-19T01:12:03.5+00:00 synnas kernel 1234 ID47 '
|
||||
b'[exampleSDID@32473 iut="3" eventSource="App\\"lication"] nfsd: server not responding')
|
||||
assert (facility_name(m.facility), severity_name(m.severity)) == ("local4", "notice")
|
||||
assert m.sent_at == datetime(2026, 10, 19, 1, 12, 3, 500000, tzinfo=timezone.utc)
|
||||
assert (m.hostname, m.app, m.text) == ("synnas", "kernel", "nfsd: server not responding")
|
||||
|
||||
|
||||
def test_rfc5424_nil_fields_and_no_zone_keep_no_sent_time():
|
||||
m = parse("<14>1 2026-10-19T01:12:03 - - - - - plain text")
|
||||
assert m.sent_at is None and (m.hostname, m.app, m.text) == ("", "", "plain text")
|
||||
|
||||
|
||||
def test_bsd_with_hostname_and_tag():
|
||||
m = parse(b"<38>Oct 9 22:14:15 adm-nas sshd[4121]: Accepted publickey for admin")
|
||||
assert (m.facility, m.severity) == (4, 6)
|
||||
assert m.sent_at is None # no year, no zone: never trusted
|
||||
assert (m.hostname, m.app, m.text) == ("adm-nas", "sshd", "Accepted publickey for admin")
|
||||
|
||||
|
||||
def test_bsd_without_hostname_reads_the_tag():
|
||||
m = parse("<30>Oct 19 01:12:03 rsyncd[881]: connect from 192.168.0.4")
|
||||
assert (m.hostname, m.app, m.text) == ("", "rsyncd", "connect from 192.168.0.4")
|
||||
|
||||
|
||||
def test_no_pri_is_user_notice_and_an_unknown_shape_is_kept_whole():
|
||||
m = parse(b"something the device made up\n")
|
||||
assert (m.facility, m.severity) == (1, 5)
|
||||
assert m.text == "something the device made up"
|
||||
assert parse(b"<999>not a pri").text == "<999>not a pri"
|
||||
|
||||
|
||||
def test_a_long_message_is_cut_and_bad_bytes_kept_readable():
|
||||
m = parse(b"<13>" + b"x" * (MAX_MESSAGE + 50))
|
||||
assert len(m.text) == MAX_MESSAGE
|
||||
assert "�" in parse(b"<13>caf\xe9").text
|
||||
|
||||
|
||||
def test_frames_octet_counted_and_newline_ended_with_a_partial_left():
|
||||
buf = bytearray(b"11 <13>hello 1<14>second line\n<15>third")
|
||||
assert frames(buf) == [b"<13>hello 1", b"<14>second line"]
|
||||
assert buf == bytearray(b"<15>third")
|
||||
buf += b" part\n"
|
||||
assert frames(buf) == [b"<15>third part"] and not buf
|
||||
|
||||
|
||||
def test_frames_waits_for_the_rest_of_a_counted_message():
|
||||
buf = bytearray(b"20 <13>only part")
|
||||
assert frames(buf) == [] and buf == bytearray(b"20 <13>only part")
|
||||
|
||||
|
||||
def test_a_count_too_large_is_read_as_text():
|
||||
buf = bytearray(b"9999999 is not a count\n")
|
||||
assert frames(buf) == [b"9999999 is not a count"]
|
||||
@@ -0,0 +1,96 @@
|
||||
"""The syslog listener (#5999): lines queued as they arrive, bounded, read in
|
||||
rounds; the listener bound as the settings say, and a port it can't open
|
||||
said, not raised."""
|
||||
import asyncio
|
||||
import socket
|
||||
from datetime import datetime, timedelta, timezone
|
||||
from types import SimpleNamespace
|
||||
|
||||
import pytest
|
||||
|
||||
from plugins.syslog import receiver
|
||||
|
||||
|
||||
@pytest.fixture(autouse=True)
|
||||
def fresh(monkeypatch):
|
||||
monkeypatch.setattr(receiver, "LISTENER", receiver.Listener())
|
||||
monkeypatch.setattr(receiver, "QUEUE", receiver.deque())
|
||||
|
||||
|
||||
def test_the_queue_is_bounded_and_says_what_it_lost(monkeypatch):
|
||||
monkeypatch.setattr(receiver, "MAX_QUEUED", 3)
|
||||
for i in range(5):
|
||||
receiver.take("10.0.0.5", f"<13>line {i}".encode())
|
||||
assert receiver.LISTENER.received == 5 and receiver.LISTENER.dropped == 2
|
||||
assert [r.message.text for r in receiver.read_round()] == ["line 2", "line 3", "line 4"]
|
||||
|
||||
|
||||
def test_a_round_takes_at_most_its_share_and_leaves_the_rest():
|
||||
for i in range(5):
|
||||
receiver.take("10.0.0.5", f"<13>line {i}".encode())
|
||||
first = receiver.read_round(limit=2)
|
||||
assert [r.message.text for r in first] == ["line 0", "line 1"] and len(receiver.QUEUE) == 3
|
||||
assert first[0].address == "10.0.0.5"
|
||||
|
||||
|
||||
def _app(**cfg):
|
||||
return SimpleNamespace(config={"PLUGINS": {"syslog": cfg}})
|
||||
|
||||
|
||||
def _free_port() -> int:
|
||||
with socket.socket() as s:
|
||||
s.bind(("0.0.0.0", 0))
|
||||
return s.getsockname()[1]
|
||||
|
||||
|
||||
def test_it_listens_on_udp_and_tcp_and_takes_what_arrives():
|
||||
async def go():
|
||||
port = _free_port()
|
||||
await receiver.ensure_listening(_app(port=port, udp=True, tcp=True))
|
||||
assert receiver.LISTENER.listening and receiver.LISTENER.error is None
|
||||
udp = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
|
||||
udp.sendto(b"<13>over udp", ("127.0.0.1", port))
|
||||
udp.close()
|
||||
reader, writer = await asyncio.wait_for(asyncio.open_connection("127.0.0.1", port), 5)
|
||||
writer.write(b"12 <13>over tcp<14>and a line\n")
|
||||
await writer.drain()
|
||||
writer.close()
|
||||
for _ in range(50):
|
||||
if len(receiver.QUEUE) >= 3:
|
||||
break
|
||||
await asyncio.sleep(0.05)
|
||||
texts = sorted(r.message.text for r in receiver.read_round())
|
||||
await receiver.close()
|
||||
return texts
|
||||
|
||||
assert asyncio.run(go()) == ["and a line", "over tcp", "over udp"]
|
||||
|
||||
|
||||
def test_a_port_it_cannot_open_is_said_and_tried_again_later():
|
||||
async def go():
|
||||
with socket.socket(socket.AF_INET, socket.SOCK_DGRAM) as held:
|
||||
held.bind(("0.0.0.0", 0))
|
||||
port = held.getsockname()[1]
|
||||
now = datetime(2026, 10, 19, 3, 0, tzinfo=timezone.utc)
|
||||
await receiver.ensure_listening(_app(port=port, udp=True, tcp=False), now)
|
||||
said = receiver.LISTENER.error
|
||||
tried = receiver.LISTENER.tried_at
|
||||
await receiver.ensure_listening(_app(port=port, udp=True, tcp=False), now + timedelta(seconds=10))
|
||||
assert receiver.LISTENER.tried_at == tried # not retried within the minute
|
||||
return said
|
||||
|
||||
said = asyncio.run(go())
|
||||
assert said and said.startswith("Port ") and "UDP" in said
|
||||
|
||||
|
||||
def test_a_change_of_port_moves_the_listener():
|
||||
async def go():
|
||||
a, b = _free_port(), _free_port()
|
||||
await receiver.ensure_listening(_app(port=a, udp=True, tcp=False))
|
||||
await receiver.ensure_listening(_app(port=b, udp=True, tcp=False))
|
||||
port = receiver.LISTENER._udp_transport.get_extra_info("sockname")[1]
|
||||
await receiver.close()
|
||||
return port, b
|
||||
|
||||
port, b = asyncio.run(go())
|
||||
assert port == b
|
||||
@@ -0,0 +1,73 @@
|
||||
"""The Syslog page (#5999): whether the listener is open or why not, the
|
||||
sources kept, and the senders offered to an admin to add or ignore."""
|
||||
from datetime import datetime, timedelta, timezone
|
||||
from types import SimpleNamespace as NS
|
||||
|
||||
from tests._templates import render_plugin_template
|
||||
from tests.test_style_tokens import hex_colours
|
||||
|
||||
|
||||
def _listener(**over):
|
||||
base = {"port": 5514, "protocols": ["UDP", "TCP"], "listening": True, "error": None,
|
||||
"bound_at": datetime.now(timezone.utc) - timedelta(hours=2), "received": 1204,
|
||||
"dropped": 0, "unoffered": 0, "connections": 1, "senders_full": False, "max_senders": 200}
|
||||
return {**base, **over}
|
||||
|
||||
|
||||
def _source(name, state, level=6, line="nfsd: server not responding", host=None):
|
||||
now = datetime.now(timezone.utc)
|
||||
return {"id": f"id-{name}", "address": "192.168.0.7", "state": state, "name": name,
|
||||
"hostname_seen": "synnas", "host": host, "first_seen_at": now - timedelta(days=1),
|
||||
"last_seen_at": now - timedelta(minutes=3), "lines_total": 1204,
|
||||
"severity": "err" if level == 3 else "info", "level": level, "last_line": line,
|
||||
"suggested_host": "h1"}
|
||||
|
||||
|
||||
async def _render(app, role, **ctx):
|
||||
from quart import session
|
||||
ctx = {"listener": _listener(), "sources": [], "offered": [], "ignored": [],
|
||||
"hosts": [NS(id="h1", name="SynNAS", address="192.168.0.7")],
|
||||
"now": datetime.now(timezone.utc), **ctx}
|
||||
async with app.test_request_context("/plugins/syslog/"):
|
||||
session["user_role"] = role
|
||||
page = await render_plugin_template(app, "syslog", "syslog/index.html", **ctx)
|
||||
return " ".join(page.split())
|
||||
|
||||
|
||||
async def test_an_offered_sender_can_be_added_or_ignored_by_an_admin(app):
|
||||
page = await _render(app, "admin", offered=[_source("synnas", "offered", level=3)])
|
||||
assert "Sending, not added" in page and "calls itself synnas" in page
|
||||
assert 'action="/plugins/syslog/sources/id-synnas/add"' in page
|
||||
assert 'action="/plugins/syslog/sources/id-synnas/ignore"' in page
|
||||
assert '<option value="h1" selected>SynNAS</option>' in page # the host at its address
|
||||
assert 'class="tone-crit">err</span> nfsd: server not responding' in page
|
||||
assert "UDP and TCP port 5514" in page and "1,204 lines received" in page
|
||||
main = page[page.index("<main"):]
|
||||
assert "font-weight:600" not in main and not hex_colours(main), hex_colours(main)
|
||||
|
||||
|
||||
async def test_a_viewer_sees_sources_but_no_controls(app):
|
||||
page = await _render(app, "viewer", sources=[_source("SynNAS", "accepted", host=NS(id="h1", name="SynNAS"))],
|
||||
offered=[_source("router", "offered")])
|
||||
assert 'href="/hosts/h1"' in page and "/plugins/syslog/sources/" not in page
|
||||
assert "Sending, not added" in page
|
||||
|
||||
|
||||
async def test_a_port_it_cannot_open_is_said(app):
|
||||
page = await _render(app, "admin", listener=_listener(
|
||||
listening=False, error="Port 514 couldn't be opened (UDP: Permission denied)."))
|
||||
assert "Not listening" in page and "Port 514 couldn't be opened" in page
|
||||
assert "below 1024" in page
|
||||
assert "No sources yet." in page
|
||||
|
||||
|
||||
async def test_the_edit_page_has_its_trail_and_a_remove(app):
|
||||
from quart import session
|
||||
source = NS(id="s1", name="SynNAS", hostname_seen="synnas", address="192.168.0.7", host_id=None)
|
||||
async with app.test_request_context("/plugins/syslog/sources/s1/edit"):
|
||||
session["user_role"] = "admin"
|
||||
page = await render_plugin_template(app, "syslog", "syslog/edit.html", source=source,
|
||||
hosts=[], label="SynNAS")
|
||||
page = " ".join(page.split())
|
||||
assert 'href="/plugins/syslog/">Syslog</a>' in page
|
||||
assert 'action="/plugins/syslog/sources/s1/delete"' in page and "data-confirm=" in page
|
||||
Reference in New Issue
Block a user