diff --git a/esphome/components/syslog/esphome_syslog.cpp b/esphome/components/syslog/esphome_syslog.cpp index d48fb4f15..83ad6b272 100644 --- a/esphome/components/syslog/esphome_syslog.cpp +++ b/esphome/components/syslog/esphome_syslog.cpp @@ -33,15 +33,7 @@ void Syslog::log_(const int level, const char *tag, const char *message, size_t severity = LOG_LEVEL_TO_SYSLOG_SEVERITY[level]; } int pri = this->facility_ * 8 + severity; - auto now = this->time_->now(); - std::string timestamp; - if (now.is_valid()) { - timestamp = now.strftime("%b %e %H:%M:%S"); - } else { - // RFC 5424: A syslog application MUST use the NILVALUE as TIMESTAMP if the syslog application is incapable of - // obtaining system time. - timestamp = "-"; - } + size_t len = message_len; // remove color formatting if (this->strip_ && message[0] == 0x1B && len > 11) { @@ -49,8 +41,40 @@ void Syslog::log_(const int level, const char *tag, const char *message, size_t len -= 11; } - auto data = str_sprintf("<%d>%s %s %s: %.*s", pri, timestamp.c_str(), App.get_name().c_str(), tag, len, message); - this->parent_->send_packet((const uint8_t *) data.data(), data.size()); + // Build syslog packet on stack (508 bytes chosen as practical limit for syslog over UDP) + char packet[508]; + size_t offset = 0; + size_t remaining = sizeof(packet); + + // Write PRI - abort if this fails as packet would be malformed + int ret = snprintf(packet, remaining, "<%d>", pri); + if (ret <= 0 || static_cast(ret) >= remaining) { + return; + } + offset = ret; + remaining -= ret; + + // Write timestamp directly into packet (RFC 5424: use "-" if time not valid or strftime fails) + auto now = this->time_->now(); + size_t ts_written = now.is_valid() ? now.strftime(packet + offset, remaining, "%b %e %H:%M:%S") : 0; + if (ts_written > 0) { + offset += ts_written; + remaining -= ts_written; + } else if (remaining > 0) { + packet[offset++] = '-'; + remaining--; + } + + // Write hostname, tag, and message + ret = snprintf(packet + offset, remaining, " %s %s: %.*s", App.get_name().c_str(), tag, (int) len, message); + if (ret > 0) { + // snprintf returns chars that would be written; clamp to actual buffer space + offset += std::min(static_cast(ret), remaining > 0 ? remaining - 1 : 0); + } + + if (offset > 0) { + this->parent_->send_packet(reinterpret_cast(packet), offset); + } } } // namespace esphome::syslog diff --git a/tests/integration/fixtures/syslog.yaml b/tests/integration/fixtures/syslog.yaml new file mode 100644 index 000000000..df376087e --- /dev/null +++ b/tests/integration/fixtures/syslog.yaml @@ -0,0 +1,43 @@ +esphome: + name: syslog-test + +host: + +api: + services: + - service: log_long_message + then: + - lambda: |- + // Log a message that exceeds 508 bytes to test truncation + ESP_LOGI("trunctest", "START|%s|END", + "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA" + "BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB" + "CCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC" + "DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD" + "EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE" + "FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF"); + - service: log_short_message + then: + - lambda: |- + // Log a short message that should arrive complete (not truncated) + ESP_LOGI("shorttest", "BEGIN|SHORT_MESSAGE_CONTENT|FINISH"); + +logger: + level: DEBUG + +time: + - platform: host + id: host_time + +udp: + - id: syslog_udp + addresses: + - "127.0.0.1" + +syslog: + udp_id: syslog_udp + time_id: host_time + port: SYSLOG_PORT_PLACEHOLDER + level: DEBUG + strip: true + facility: 16 diff --git a/tests/integration/test_syslog.py b/tests/integration/test_syslog.py new file mode 100644 index 000000000..b31a19392 --- /dev/null +++ b/tests/integration/test_syslog.py @@ -0,0 +1,284 @@ +"""Integration test for syslog component.""" + +from __future__ import annotations + +import asyncio +from collections.abc import AsyncGenerator +import contextlib +from contextlib import asynccontextmanager +from dataclasses import dataclass, field +import re +import socket +from typing import TypedDict + +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + + +class ParsedSyslogMessage(TypedDict): + """Parsed syslog message components.""" + + pri: int + facility: int + severity: int + timestamp: str + hostname: str + tag: str + message: str + + +# RFC 3164 syslog message pattern: +# TIMESTAMP HOSTNAME TAG: MESSAGE +# Example: <134>Dec 20 14:30:45 syslog-test app: [D][app:029]: Running... +SYSLOG_PATTERN = re.compile( + r"<(\d+)>" # PRI (priority = facility * 8 + severity) + r"(\S+ +\d+ \d+:\d+:\d+|-)" # TIMESTAMP (BSD-style "%b %e %H:%M:%S", e.g. "Dec 20 14:30:45", or NILVALUE "-") + r" (\S+)" # HOSTNAME + r" (\S+):" # TAG + r" (.*)" # MESSAGE +) + + +@dataclass +class SyslogReceiver: + """Collects syslog messages received over UDP.""" + + messages: list[str] = field(default_factory=list) + message_received: asyncio.Event = field(default_factory=asyncio.Event) + _waiters: list[tuple[re.Pattern, asyncio.Event]] = field(default_factory=list) + + def on_message(self, msg: str) -> None: + """Called when a message is received.""" + self.messages.append(msg) + self.message_received.set() + # Check pattern waiters + for pattern, event in self._waiters: + if pattern.search(msg): + event.set() + + async def wait_for_messages(self, timeout: float = 10.0) -> None: + """Wait for at least one message to be received.""" + await asyncio.wait_for(self.message_received.wait(), timeout=timeout) + + async def wait_for_pattern(self, pattern: str, timeout: float = 5.0) -> str: + """Wait for a message matching the pattern.""" + compiled = re.compile(pattern) + event = asyncio.Event() + self._waiters.append((compiled, event)) + try: + # Check existing messages first + for msg in self.messages: + if compiled.search(msg): + return msg + # Wait for new message + await asyncio.wait_for(event.wait(), timeout=timeout) + # Find and return the matching message + for msg in reversed(self.messages): + if compiled.search(msg): + return msg + raise RuntimeError("Event set but no matching message found") + finally: + self._waiters.remove((compiled, event)) + + +@asynccontextmanager +async def syslog_udp_listener() -> AsyncGenerator[tuple[int, SyslogReceiver]]: + """Async context manager that listens for syslog UDP messages. + + Yields: + Tuple of (port, SyslogReceiver) where port is the UDP port to send to + and SyslogReceiver contains the received messages. + """ + # Create and bind UDP socket + sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + sock.bind(("127.0.0.1", 0)) + sock.setblocking(False) + port = sock.getsockname()[1] + + receiver = SyslogReceiver() + + async def receive_messages() -> None: + """Background task to receive syslog messages.""" + loop = asyncio.get_running_loop() + while True: + try: + data = await loop.sock_recv(sock, 4096) + if data: + msg = data.decode("utf-8", errors="replace") + receiver.on_message(msg) + except BlockingIOError: + await asyncio.sleep(0.01) + except Exception: + break + + task = asyncio.create_task(receive_messages()) + try: + yield port, receiver + finally: + task.cancel() + with contextlib.suppress(asyncio.CancelledError): + await task + sock.close() + + +def parse_syslog_message(msg: str) -> ParsedSyslogMessage | None: + """Parse a syslog message and return its components.""" + match = SYSLOG_PATTERN.match(msg) + if not match: + return None + pri, timestamp, hostname, tag, message = match.groups() + pri_val = int(pri) + # PRI = facility * 8 + severity + facility = pri_val // 8 + severity = pri_val % 8 + return ParsedSyslogMessage( + pri=pri_val, + facility=facility, + severity=severity, + timestamp=timestamp, + hostname=hostname, + tag=tag, + message=message, + ) + + +@pytest.mark.asyncio +async def test_syslog( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Test syslog component sends properly formatted messages.""" + async with syslog_udp_listener() as (udp_port, receiver): + # Replace the placeholder port in the config + config = yaml_config.replace("SYSLOG_PORT_PLACEHOLDER", str(udp_port)) + + async with run_compiled(config), api_client_connected() as client: + # Verify device is running + device_info = await client.device_info() + assert device_info is not None + assert device_info.name == "syslog-test" + + # Wait for syslog messages (ESPHome logs during startup) + try: + await receiver.wait_for_messages(timeout=10.0) + except TimeoutError: + pytest.fail("No syslog messages received within timeout") + + # Give it a moment to collect more messages + await asyncio.sleep(0.5) + + # Verify we received messages + assert len(receiver.messages) > 0, "No syslog messages received" + + # Parse and validate all messages + parsed_messages: list[ParsedSyslogMessage] = [] + for msg in receiver.messages: + parsed = parse_syslog_message(msg) + if parsed: + parsed_messages.append(parsed) + + assert len(parsed_messages) > 0, ( + f"No valid syslog messages found. Received: {receiver.messages[:5]}" + ) + + # Validate message format for all parsed messages + for parsed in parsed_messages: + # Validate PRI is in valid range (0-191) + assert 0 <= parsed["pri"] <= 191, f"Invalid PRI: {parsed['pri']}" + + # Validate facility matches config (16 = local0) + assert parsed["facility"] == 16, ( + f"Expected facility 16, got {parsed['facility']}" + ) + + # Validate severity is in valid range (0-7) + assert 0 <= parsed["severity"] <= 7, ( + f"Invalid severity: {parsed['severity']}" + ) + + # Validate hostname matches device name + assert parsed["hostname"] == "syslog-test", ( + f"Unexpected hostname: {parsed['hostname']}" + ) + + # Validate timestamp format (BSD or NILVALUE) + if parsed["timestamp"] != "-": + assert re.match( + r"[A-Z][a-z]{2} +\d+ \d{2}:\d{2}:\d{2}", + parsed["timestamp"], + ), f"Invalid timestamp format: {parsed['timestamp']}" + + # Verify we see different severity levels in the logs + severities_seen = {p["severity"] for p in parsed_messages} + # ESPHome startup logs should include at least INFO (5) or DEBUG (7) + assert len(severities_seen) >= 1, "Expected to see at least one severity" + + # Verify messages don't contain ANSI color codes (strip=true) + for parsed in parsed_messages: + assert "\x1b[" not in parsed["message"], ( + f"Color codes not stripped: {parsed['message'][:50]}" + ) + + # Verify message content is not empty for most messages + non_empty_messages = [p for p in parsed_messages if p["message"].strip()] + assert len(non_empty_messages) > 0, "All messages are empty" + + # Verify tag format (should be component name like "app", "wifi", etc.) + for parsed in parsed_messages: + assert len(parsed["tag"]) > 0, "Empty tag" + # Tag should not contain spaces or colons + assert " " not in parsed["tag"], f"Tag contains space: {parsed['tag']}" + + # Test message truncation - call service that logs a very long message + _, services = await client.list_entities_services() + log_service = next( + (s for s in services if s.name == "log_long_message"), None + ) + assert log_service is not None, "log_long_message service not found" + + # Call the service to trigger a long log message + await client.execute_service(log_service, {}) + + # Wait specifically for the truncation test message + try: + trunc_msg = await receiver.wait_for_pattern(r"trunctest.*START\|") + except TimeoutError: + pytest.fail( + f"Truncation test message not received. Got: {receiver.messages}" + ) + + # Verify message is truncated to max 508 bytes + assert len(trunc_msg) <= 508, f"Message exceeds 508 bytes: {len(trunc_msg)}" + + # Verify the message starts correctly but is truncated (no "|END") + assert "START|" in trunc_msg, "Message should contain START marker" + assert "|END" not in trunc_msg, ( + "Message should be truncated before END marker" + ) + + # Test short message - should arrive complete (not truncated) + short_service = next( + (s for s in services if s.name == "log_short_message"), None + ) + assert short_service is not None, "log_short_message service not found" + + await client.execute_service(short_service, {}) + + try: + short_msg = await receiver.wait_for_pattern(r"shorttest.*BEGIN\|") + except TimeoutError: + pytest.fail( + f"Short test message not received. Got: {receiver.messages[-10:]}" + ) + + # Verify short message arrived complete with both markers + assert "BEGIN|" in short_msg, "Short message missing BEGIN marker" + assert "|FINISH" in short_msg, ( + f"Short message truncated unexpectedly: {short_msg}" + ) + assert "SHORT_MESSAGE_CONTENT" in short_msg, ( + f"Short message content missing: {short_msg}" + )