From 7ff57032500e2a2addaa97530fa9c7f976bcfc7e Mon Sep 17 00:00:00 2001 From: anti Date: Tue, 14 Apr 2026 02:07:35 -0400 Subject: [PATCH] feat: SSH log relay emits proper DECNET syslog for sshd events New log_relay.py replaces raw 'cat' on the rsyslog pipe. Intercepts sshd and bash lines and re-emits them as structured RFC 5424 events: login_success, session_opened, disconnect, connection_closed, command. Parsers updated to accept non-nil PROCID (sshd uses PID). --- decnet/collector/worker.py | 14 +---- decnet/correlation/parser.py | 16 +---- templates/ssh/Dockerfile | 2 + templates/ssh/entrypoint.sh | 4 +- templates/ssh/log_relay.py | 106 +++++++++++++++++++++++++++++++ tests/test_collector.py | 26 ++------ tests/test_correlation.py | 34 +++------- tests/test_ssh_log_relay.py | 117 +++++++++++++++++++++++++++++++++++ 8 files changed, 240 insertions(+), 79 deletions(-) create mode 100644 templates/ssh/log_relay.py create mode 100644 tests/test_ssh_log_relay.py diff --git a/decnet/collector/worker.py b/decnet/collector/worker.py index b948bf1..4dc7b8a 100644 --- a/decnet/collector/worker.py +++ b/decnet/collector/worker.py @@ -24,7 +24,7 @@ _RFC5424_RE = re.compile( r"(\S+) " # 1: TIMESTAMP r"(\S+) " # 2: HOSTNAME (decky name) r"(\S+) " # 3: APP-NAME (service) - r"- " # PROCID always NILVALUE + r"\S+ " # PROCID (NILVALUE or PID) r"(\S+) " # 4: MSGID (event_type) r"(.+)$", # 5: SD element + optional MSG ) @@ -32,8 +32,6 @@ _SD_BLOCK_RE = re.compile(r'\[decnet@55555\s+(.*?)\]', re.DOTALL) _PARAM_RE = re.compile(r'(\w+)="((?:[^"\\]|\\.)*)"') _IP_FIELDS = ("src_ip", "src", "client_ip", "remote_ip", "ip") -# bash PROMPT_COMMAND logger output: "CMD uid=0 pwd=/root cmd=ls -lah" -_BASH_CMD_RE = re.compile(r"CMD\s+uid=(\S+)\s+pwd=(\S+)\s+cmd=(.*)") @@ -74,16 +72,6 @@ def parse_rfc5424(line: str) -> Optional[dict[str, Any]]: except ValueError: ts_formatted = ts_raw - # Normalize bash CMD lines from SSH honeypot PROMPT_COMMAND logger - if service == "bash" and msg: - cmd_match = _BASH_CMD_RE.match(msg) - if cmd_match: - service = "ssh" - event_type = "command" - fields["uid"] = cmd_match.group(1) - fields["pwd"] = cmd_match.group(2) - fields["command"] = cmd_match.group(3) - return { "timestamp": ts_formatted, "decky": decky, diff --git a/decnet/correlation/parser.py b/decnet/correlation/parser.py index 5411d3e..9fa7420 100644 --- a/decnet/correlation/parser.py +++ b/decnet/correlation/parser.py @@ -26,7 +26,7 @@ _RFC5424_RE = re.compile( r"(\S+) " # 1: TIMESTAMP r"(\S+) " # 2: HOSTNAME (decky name) r"(\S+) " # 3: APP-NAME (service) - r"- " # PROCID always NILVALUE + r"\S+ " # PROCID (NILVALUE or PID) r"(\S+) " # 4: MSGID (event_type) r"(.+)$", # 5: SD element + optional MSG ) @@ -40,8 +40,6 @@ _PARAM_RE = re.compile(r'(\w+)="((?:[^"\\]|\\.)*)"') # Field names to probe for attacker IP, in priority order _IP_FIELDS = ("src_ip", "src", "client_ip", "remote_ip", "ip") -# bash PROMPT_COMMAND logger output: "CMD uid=0 pwd=/root cmd=ls -lah" -_BASH_CMD_RE = re.compile(r"CMD\s+uid=(\S+)\s+pwd=(\S+)\s+cmd=(.*)") @dataclass @@ -103,18 +101,6 @@ def parse_line(line: str) -> LogEvent | None: fields = _parse_sd_params(sd_rest) - # Normalize bash CMD lines from SSH honeypot PROMPT_COMMAND logger - if service == "bash": - # Free-text MSG follows the SD element (which is "-" for these lines) - msg = sd_rest.lstrip("- ").strip() - cmd_match = _BASH_CMD_RE.match(msg) - if cmd_match: - service = "ssh" - event_type = "command" - fields["uid"] = cmd_match.group(1) - fields["pwd"] = cmd_match.group(2) - fields["command"] = cmd_match.group(3) - attacker_ip = _extract_attacker_ip(fields) return LogEvent( diff --git a/templates/ssh/Dockerfile b/templates/ssh/Dockerfile index 230d429..5eeacc4 100644 --- a/templates/ssh/Dockerfile +++ b/templates/ssh/Dockerfile @@ -65,6 +65,8 @@ RUN mkdir -p /root/projects /root/backups /var/www/html && \ printf 'DB_HOST=10.0.0.5\nDB_USER=admin\nDB_PASS=changeme123\nDB_NAME=prod_db\n' > /root/projects/.env && \ printf '[Unit]\nDescription=App Server\n[Service]\nExecStart=/usr/bin/python3 /opt/app/server.py\n' > /root/projects/app.service +COPY decnet_logging.py /opt/decnet_logging.py +COPY log_relay.py /opt/log_relay.py COPY entrypoint.sh /entrypoint.sh RUN chmod +x /entrypoint.sh diff --git a/templates/ssh/entrypoint.sh b/templates/ssh/entrypoint.sh index c5c8291..b9090fe 100644 --- a/templates/ssh/entrypoint.sh +++ b/templates/ssh/entrypoint.sh @@ -34,8 +34,8 @@ fi # Logging pipeline: named pipe → rsyslogd (RFC 5424) → stdout → Docker log capture mkfifo /var/run/decnet-logs -# Relay pipe to stdout so Docker captures all syslog events -cat /var/run/decnet-logs & +# Relay pipe through Python log_relay — normalizes sshd/bash events to DECNET format +python3 /opt/log_relay.py & # Start rsyslog (reads /etc/rsyslog.d/99-decnet.conf, writes to the pipe above) rsyslogd diff --git a/templates/ssh/log_relay.py b/templates/ssh/log_relay.py new file mode 100644 index 0000000..5fefb00 --- /dev/null +++ b/templates/ssh/log_relay.py @@ -0,0 +1,106 @@ +#!/usr/bin/env python3 +""" +SSH log relay — reads rsyslog output from the named pipe and re-emits +matched sshd/bash events as proper DECNET RFC 5424 syslog lines to stdout. + +Matched events: + - Accepted password (login_success) + - Connection closed (connection_closed) + - Disconnected from user (disconnect) + - Session opened (session_opened) + - bash CMD (command) +""" + +import os +import re +import sys + +from decnet_logging import syslog_line, write_syslog_file, SEVERITY_INFO, SEVERITY_WARNING + +NODE_NAME = os.environ.get("NODE_NAME", "ssh-decky") +SERVICE = "ssh" + +# sshd patterns +_ACCEPTED_RE = re.compile( + r"Accepted (\S+) for (\S+) from (\S+) port (\d+)" +) +_SESSION_RE = re.compile( + r"session opened for user (\S+?)(?:\(uid=\d+\))? by" +) +_DISCONNECTED_RE = re.compile( + r"Disconnected from user (\S+) (\S+) port (\d+)" +) +_CONN_CLOSED_RE = re.compile( + r"Connection closed by (\S+) port (\d+)" +) + +# bash PROMPT_COMMAND pattern +_BASH_CMD_RE = re.compile( + r"CMD\s+uid=(\S+)\s+pwd=(\S+)\s+cmd=(.*)" +) + + +def _handle_line(line: str) -> None: + """Parse a raw rsyslog line and emit a DECNET syslog line if it matches.""" + + # --- Accepted password --- + m = _ACCEPTED_RE.search(line) + if m: + method, user, src_ip, port = m.groups() + write_syslog_file(syslog_line( + SERVICE, NODE_NAME, "login_success", SEVERITY_WARNING, + src_ip=src_ip, username=user, auth_method=method, src_port=port, + )) + return + + # --- Session opened --- + m = _SESSION_RE.search(line) + if m: + user = m.group(1) + write_syslog_file(syslog_line( + SERVICE, NODE_NAME, "session_opened", SEVERITY_INFO, + username=user, + )) + return + + # --- Disconnected from user --- + m = _DISCONNECTED_RE.search(line) + if m: + user, src_ip, port = m.groups() + write_syslog_file(syslog_line( + SERVICE, NODE_NAME, "disconnect", SEVERITY_INFO, + src_ip=src_ip, username=user, src_port=port, + )) + return + + # --- Connection closed --- + m = _CONN_CLOSED_RE.search(line) + if m: + src_ip, port = m.groups() + write_syslog_file(syslog_line( + SERVICE, NODE_NAME, "connection_closed", SEVERITY_INFO, + src_ip=src_ip, src_port=port, + )) + return + + # --- bash CMD --- + m = _BASH_CMD_RE.search(line) + if m: + uid, pwd, cmd = m.groups() + write_syslog_file(syslog_line( + SERVICE, NODE_NAME, "command", SEVERITY_INFO, + uid=uid, pwd=pwd, command=cmd, + )) + return + + +def main() -> None: + pipe_path = "/var/run/decnet-logs" + while True: + with open(pipe_path, "r") as pipe: + for line in pipe: + _handle_line(line.rstrip("\n")) + + +if __name__ == "__main__": + main() diff --git a/tests/test_collector.py b/tests/test_collector.py index 2549788..ca99e4c 100644 --- a/tests/test_collector.py +++ b/tests/test_collector.py @@ -131,30 +131,12 @@ class TestParseRfc5424: assert result["msg"] == "login attempt" - def test_bash_cmd_normalized_to_ssh_command(self): - line = '<14>1 2026-04-14T05:48:12.628417+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=ls /var/www/html' + def test_non_nil_procid_accepted(self): + line = '<38>1 2026-04-14T05:48:12.611006+00:00 SRV-BRAVO-13 sshd 282 - - Accepted password for root from 192.168.1.5 port 50854 ssh2' result = parse_rfc5424(line) assert result is not None - assert result["service"] == "ssh" - assert result["event_type"] == "command" - assert result["fields"]["command"] == "ls /var/www/html" - assert result["fields"]["uid"] == "0" - assert result["fields"]["pwd"] == "/root" - - def test_bash_cmd_simple_command(self): - line = '<14>1 2026-04-14T05:48:13.332072+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=ls' - result = parse_rfc5424(line) - assert result is not None - assert result["service"] == "ssh" - assert result["event_type"] == "command" - assert result["fields"]["command"] == "ls" - - def test_bash_non_cmd_not_normalized(self): - line = '<14>1 2026-04-14T05:48:12.628417+00:00 SRV-BRAVO-13 bash - - - some other bash message' - result = parse_rfc5424(line) - assert result is not None - assert result["service"] == "bash" - assert result["event_type"] == "-" + assert result["service"] == "sshd" + assert result["decky"] == "SRV-BRAVO-13" class TestIsServiceContainer: diff --git a/tests/test_correlation.py b/tests/test_correlation.py index be4ca0e..cb186e1 100644 --- a/tests/test_correlation.py +++ b/tests/test_correlation.py @@ -155,37 +155,17 @@ class TestParserAttackerIP: assert parse_line(line) is None -class TestParserBashNormalization: - def test_bash_cmd_normalized_to_ssh_command(self): - line = '<14>1 2026-04-14T05:48:12.628417+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=ls /var/www/html' +class TestParserProcidFlexibility: + def test_non_nil_procid_accepted(self): + line = '<38>1 2026-04-14T05:48:12.611006+00:00 SRV-BRAVO-13 sshd 282 - - Accepted password for root' event = parse_line(line) assert event is not None - assert event.service == "ssh" - assert event.event_type == "command" - assert event.fields["command"] == "ls /var/www/html" - assert event.fields["uid"] == "0" - assert event.fields["pwd"] == "/root" + assert event.service == "sshd" + assert event.decky == "SRV-BRAVO-13" - def test_bash_cmd_simple(self): - line = '<14>1 2026-04-14T05:48:13.332072+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=ls' - event = parse_line(line) + def test_nil_procid_still_works(self): + event = parse_line(_make_line()) assert event is not None - assert event.service == "ssh" - assert event.fields["command"] == "ls" - - def test_bash_non_cmd_stays_as_bash(self): - line = '<14>1 2026-04-14T05:48:12.628417+00:00 SRV-BRAVO-13 bash - - - some other bash message' - event = parse_line(line) - assert event is not None - assert event.service == "bash" - assert event.event_type == "-" - - def test_bash_cmd_with_complex_command(self): - line = '<14>1 2026-04-14T05:48:32.006502+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=cat /etc/passwd | grep root' - event = parse_line(line) - assert event is not None - assert event.service == "ssh" - assert event.fields["command"] == "cat /etc/passwd | grep root" # --------------------------------------------------------------------------- diff --git a/tests/test_ssh_log_relay.py b/tests/test_ssh_log_relay.py new file mode 100644 index 0000000..7745ab1 --- /dev/null +++ b/tests/test_ssh_log_relay.py @@ -0,0 +1,117 @@ +"""Tests for the SSH log relay that normalizes sshd/bash events.""" + +import os +import sys +import types +from pathlib import Path + +import pytest + +_SSH_TPL = str(Path(__file__).resolve().parent.parent / "templates" / "ssh") + + +def _load_relay(): + """Import log_relay with a real decnet_logging from the SSH template dir.""" + # Clear any stale stubs + for mod_name in ("decnet_logging", "log_relay"): + sys.modules.pop(mod_name, None) + + if _SSH_TPL not in sys.path: + sys.path.insert(0, _SSH_TPL) + + import log_relay + return log_relay + + +_relay = _load_relay() + + +def _capture(line: str) -> str | None: + """Run _handle_line, collect output via monkey-patched write_syslog_file.""" + collected: list[str] = [] + original = _relay.write_syslog_file + _relay.write_syslog_file = lambda s: collected.append(s) + try: + _relay._handle_line(line) + finally: + _relay.write_syslog_file = original + return collected[0] if collected else None + + +class TestSshdAcceptedPassword: + def test_accepted_password_emits_login_success(self): + emitted = _capture( + '<38>1 2026-04-14T05:48:12.611006+00:00 SRV-BRAVO-13 sshd 282 - - Accepted password for root from 192.168.1.5 port 50854 ssh2' + ) + assert emitted is not None + assert "login_success" in emitted + assert 'src_ip="192.168.1.5"' in emitted + assert 'username="root"' in emitted + assert 'auth_method="password"' in emitted + + def test_accepted_publickey(self): + emitted = _capture( + '<38>1 2026-04-14T05:48:12.611006+00:00 SRV-BRAVO-13 sshd 282 - - Accepted publickey for admin from 10.0.0.1 port 12345 ssh2' + ) + assert emitted is not None + assert 'auth_method="publickey"' in emitted + assert 'username="admin"' in emitted + + +class TestSshdSessionOpened: + def test_session_opened(self): + emitted = _capture( + '<86>1 2026-04-14T05:48:12.611880+00:00 SRV-BRAVO-13 sshd 282 - - pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)' + ) + assert emitted is not None + assert "session_opened" in emitted + assert 'username="root"' in emitted + + +class TestSshdDisconnected: + def test_disconnected(self): + emitted = _capture( + '<38>1 2026-04-14T05:54:50.710536+00:00 SRV-BRAVO-13 sshd 282 - - Disconnected from user root 192.168.1.5 port 50854' + ) + assert emitted is not None + assert "disconnect" in emitted + assert 'src_ip="192.168.1.5"' in emitted + assert 'username="root"' in emitted + + +class TestSshdConnectionClosed: + def test_connection_closed(self): + emitted = _capture( + '<38>1 2026-04-14T05:47:55.621236+00:00 SRV-BRAVO-13 sshd 280 - - Connection closed by 192.168.1.5 port 52900 [preauth]' + ) + assert emitted is not None + assert "connection_closed" in emitted + assert 'src_ip="192.168.1.5"' in emitted + + +class TestBashCommand: + def test_bash_cmd(self): + emitted = _capture( + '<14>1 2026-04-14T05:48:12.628417+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=ls /var/www/html' + ) + assert emitted is not None + assert "command" in emitted + assert 'command="ls /var/www/html"' in emitted + + def test_bash_cmd_with_pipes(self): + emitted = _capture( + '<14>1 2026-04-14T05:48:32.006502+00:00 SRV-BRAVO-13 bash - - - CMD uid=0 pwd=/root cmd=cat /etc/passwd | grep root' + ) + assert emitted is not None + assert "cat /etc/passwd | grep root" in emitted + + +class TestUnmatchedLines: + def test_pam_env_ignored(self): + assert _capture('<83>1 2026-04-14T05:48:12.615198+00:00 SRV-BRAVO-13 sshd 282 - - pam_env(sshd:session): Unable to open env file') is None + + def test_session_closed_ignored(self): + assert _capture('<86>1 2026-04-14T05:54:50.710577+00:00 SRV-BRAVO-13 sshd 282 - - pam_unix(sshd:session): session closed for user root') is None + + def test_syslogin_ignored(self): + assert _capture('<38>1 2026-04-14T05:54:50.710307+00:00 SRV-BRAVO-13 sshd 282 - - syslogin_perform_logout: logout() returned an error') is None