diff --git a/.env b/.env new file mode 100644 index 00000000..ad38630f --- /dev/null +++ b/.env @@ -0,0 +1,5 @@ +# IP адрес Unified Agent. При MODE=dev независимо от значения переменной логи отправляются на localhost +UNIFIED_AGENT_URL="http://130.193.58.218:22132" + +# Режим работы: dev (локальный PostgreSQL) или prod (Yandex Cloud PostgreSQL) +MODE=prod diff --git a/.github/workflows/back_test.yml b/.github/workflows/back_test.yml index 4932c240..19e3d047 100644 --- a/.github/workflows/back_test.yml +++ b/.github/workflows/back_test.yml @@ -17,6 +17,11 @@ jobs: with: python-version: ${{ matrix.python-version }} + - name: Create .env file with MODE=dev + run: | + touch .env + echo "MODE=dev" >> .env + - name: Install apt package run: | sudo apt-get update \ diff --git a/.github/workflows/full_test.yml b/.github/workflows/full_test.yml index 8e6ff1f3..2b272fe7 100644 --- a/.github/workflows/full_test.yml +++ b/.github/workflows/full_test.yml @@ -15,8 +15,8 @@ jobs: - name: Start frontend run: | - cd front/ sed -i 's/MODE=prod/MODE=dev/' .env + cd front/ sed -i '/^BASE_DOMAIN/d' .env sed -i '/^ALLOWED_HOSTS/d' .env && printf "\nALLOWED_HOSTS=http://localhost,http://172.18.0.2,http://172.18.0.3" >> .env docker compose up -d diff --git a/.gitignore b/.gitignore index 0f6a4998..faf58104 100644 --- a/.gitignore +++ b/.gitignore @@ -7,7 +7,7 @@ vk_auth.json __init__.py eslint.config.mjs back/rabbitmq/rabbitmq/ -.env *.log *.ini -front/rabbitmq/rabbitmq \ No newline at end of file +front/rabbitmq/rabbitmq +!.env \ No newline at end of file diff --git a/back/.env b/back/.env index 09b65b33..7ee86446 100755 --- a/back/.env +++ b/back/.env @@ -4,4 +4,5 @@ celery_concurrency=1 queue_names=queue1,queue2,queue3 exchange_name=default_exchange RABBITMQ_DEFAULT_USER=user -RABBITMQ_DEFAULT_PASS=password \ No newline at end of file +RABBITMQ_DEFAULT_PASS=password +CELERY_LOG_GROUP="e236kkv3il7sf922kato" diff --git a/back/docker-compose.yml b/back/docker-compose.yml index 02b45d49..0d6c9bd5 100644 --- a/back/docker-compose.yml +++ b/back/docker-compose.yml @@ -11,6 +11,7 @@ services: restart: always env_file: - .env + - ../.env environment: - celery_concurrency=${celery_concurrency} - queue_names=${queue_names} diff --git a/back/requirements.txt b/back/requirements.txt index 0c083992..9f1ab7e5 100644 --- a/back/requirements.txt +++ b/back/requirements.txt @@ -4,4 +4,5 @@ python-dotenv==1.1.1 marshmallow_dataclass==8.7.1 psutil==7.0.0 netaddr==1.3.0 -ipmininet @ git+https://github.com/mimi-net/ipmininet.git@1.2.4 \ No newline at end of file +ipmininet @ git+https://github.com/mimi-net/ipmininet.git@1.2.4 +requests==2.34.0 diff --git a/back/src/emulator.py b/back/src/emulator.py index 3a91e2b4..b4303ef5 100644 --- a/back/src/emulator.py +++ b/back/src/emulator.py @@ -2,9 +2,9 @@ import os.path import subprocess import time - import dpkt - +import logging +import logging_config from ipmininet.ipnet import IPNet from jobs import Jobs from network import MiminetNetwork @@ -13,6 +13,9 @@ from mininet.log import setLogLevel, info, error from network_topology import MiminetTopology +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) + def emulate( network: Network, @@ -26,6 +29,15 @@ def emulate( tuple: animation list and pcap files. """ + start_ts = time.time() + + logger.info( + "Emulation started", + extra={ + "jobs_count": len(network.jobs) if getattr(network, "jobs", None) else 0 + }, + ) + setLogLevel("info") # Validate job limit @@ -42,7 +54,6 @@ def emulate( raise ValueError( f"Превышен лимит! В сети максимальное количество команд sleep {MAX_TIME_SLEEP})." ) - if len(network.jobs) == 0: return [], [] @@ -125,6 +136,9 @@ def emulate( net.stop() except Exception as e: + + logger.error("Miminet configuration failed", extra={"error": str(e)}) + error(f"An error occurred during mininet configuration: {str(e)}") subprocess.call("mn -c", shell=True) @@ -143,6 +157,15 @@ def emulate( animation = group_packets_by_time(animation) error("[emulator] Animation groups after time-grouping: %d\n" % len(animation)) + duration_ms = int((time.time() - start_ts) * 1000) + logger.info( + "Emulation finished", + extra={ + "pcaps_count": len(pcaps), + "duration_ms": duration_ms, + }, + ) + return animation, pcaps diff --git a/back/src/jobs.py b/back/src/jobs.py index 7046a302..12837485 100755 --- a/back/src/jobs.py +++ b/back/src/jobs.py @@ -2,12 +2,17 @@ import re import shlex import time -from typing import Any, Callable, Dict, List - -from ipmininet.host.config.dnsmasq import Dnsmasq -from mininet.log import info +import logging +import logging_config from netaddr import EUI, AddrFormatError +from typing import Any, Callable, List, Dict from network_schema import Job +from mininet.log import info +from ipmininet.host.config.dnsmasq import Dnsmasq + +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) +logger.setLevel(logging.DEBUG) def filter_arg_for_options( @@ -77,6 +82,11 @@ def udp_tcp_args_checker(ip, size, port) -> bool: def net_dev_checker(dev) -> bool: """Checker for net interface""" if not re.match(r"^[a-z][a-z0-9:_\-\.]{,14}$", dev): + # Log invalid interface name + logger.warning( + "Net dev is invalid", + extra={"dev": dev, "reason": "device name not matched"}, + ) return False return True @@ -85,13 +95,26 @@ def ip_addr_add_checker(ip, mask, dev) -> bool: """Checker all args in ip addr add job""" if not valid_ip(ip): + # Log invalid/empty IP for ip addr add + logger.warning( + "Ip addr add, invalid ip", + extra={"ip": ip, "mask": mask, "dev": dev}, + ) return False try: _ = int(mask) except (ValueError, TypeError): + # Log invalid mask + logger.warning( + "Ip addr add, invalid mask", extra={"ip": ip, "mask": mask, "dev": dev} + ) return False if not net_dev_checker(dev): + # Log invalid device when adding IP + logger.warning( + "Ip addr add, invalid dev", extra={"ip": ip, "mask": mask, "dev": dev} + ) return False return True @@ -137,10 +160,56 @@ def subinterface_vlan_checker(intf, ip, mask, vlan, intf_name) -> bool: def ipip_interface_checker(ip_start, ip_end, ip_int, name_int) -> bool: """Checker args for ipip_interface""" - if not valid_ip(ip_start) or not valid_ip(ip_end) or not valid_ip(ip_int): + if not valid_ip(ip_start): + # Log missing/invalid start IP of IPIP tunnel + logger.warning( + "Ipip, invalid start ip", + extra={ + "ip_start": ip_start, + "ip_end": ip_end, + "ip_int": ip_int, + "name": name_int, + }, + ) + return False + + if not valid_ip(ip_end): + # Log missing/invalid end IP of IPIP tunnel + logger.warning( + "Ipip, invalid end ip", + extra={ + "ip_start": ip_start, + "ip_end": ip_end, + "ip_int": ip_int, + "name": name_int, + }, + ) + return False + + if not valid_ip(ip_int): + # Log missing/invalid IP of IPIP interface + logger.warning( + "Ipip, invalid iface ip", + extra={ + "ip_start": ip_start, + "ip_end": ip_end, + "ip_int": ip_int, + "name": name_int, + }, + ) return False if not valid_iface(name_int): + # Log invalid IPIP interface name + logger.warning( + "Ipip, invalid iface name", + extra={ + "ip_start": ip_start, + "ip_end": ip_end, + "ip_int": ip_int, + "name": name_int, + }, + ) return False return True @@ -221,7 +290,8 @@ def link_down_handler(job: Job, job_host: Any) -> None: arg_interface = job.arg_1 if not net_dev_checker(arg_interface): return - job_host.cmd(f"ip link set {arg_interface} down") + cmd = f"ip link set {arg_interface} down" + run_command(job, job_host, cmd) def sleep_handler(job: Job, job_host: Any) -> None: @@ -231,14 +301,45 @@ def sleep_handler(job: Job, job_host: Any) -> None: time.sleep(int(arg_time)) +def run_command(job, host, command) -> str | Any | None: + """Does the same as job_host.cmd(command) and returns the same output with additional logs.""" + output = host.cmd(command) + return_code = host.cmd("echo $?") + if return_code != "0\r\n": + # Log failed command execution + logger.error( + "Job execution failed", + extra={ + "job_id": getattr(job, "job_id", None), + "host_id": getattr(job, "host_id", None), + "command": command, + "return_code": return_code, + "stderr": output, + }, + ) + else: + # Log successful command execution + logger.debug( + "Job command executed", + extra={ + "job_id": getattr(job, "job_id", None), + "host_id": getattr(job, "host_id", None), + "command": command, + "return_code": return_code, + "stdout": output, + }, + ) + return output + + def ping_handler(job: Job, job_host: Any) -> None: """Execute ping -c 1""" arg_ip = job.arg_1 if not valid_ip(arg_ip): return - - job_host.cmd(f"ping -c 1 {arg_ip}") + cmd = f"ping -c 1 {arg_ip}" + run_command(job, job_host, cmd) def ping_with_options_handler(job: Job, job_host: Any) -> None: @@ -252,8 +353,8 @@ def ping_with_options_handler(job: Job, job_host: Any) -> None: if len(arg_opt) > 0: arg_opt = ping_options_filter(arg_opt) - - job_host.cmd(f"ping -c 1 {arg_opt} {arg_ip}") + cmd = f"ping -c 1 {arg_opt} {arg_ip}" + run_command(job, job_host, cmd) def get_sending_data_argument(job: Job) -> tuple[str | int, str | int, str | int]: @@ -274,9 +375,8 @@ def sending_udp_data_handler(job: Job, job_host: Any) -> None: if not udp_tcp_args_checker(arg_ip, arg_size, arg_port): return - job_host.cmd( - f"dd if=/dev/urandom bs={arg_size} count=1 | nc -uq1 {arg_ip} {arg_port}" - ) + cmd = f"dd if=/dev/urandom bs={arg_size} count=1 | nc -uq1 {arg_ip} {arg_port}" + run_command(job, job_host, cmd) def sending_tcp_data_handler(job: Job, job_host: Any) -> None: @@ -287,9 +387,8 @@ def sending_tcp_data_handler(job: Job, job_host: Any) -> None: if not udp_tcp_args_checker(arg_ip, arg_size, arg_port): return - job_host.cmd( - f"dd if=/dev/urandom bs={arg_size} count=1 | nc -w 30 -q1 {arg_ip} {arg_port}" - ) + cmd = f"dd if=/dev/urandom bs={arg_size} count=1 | nc -w 30 -q1 {arg_ip} {arg_port}" + run_command(job, job_host, cmd) def traceroute_handler(job: Job, job_host: Any) -> None: @@ -304,7 +403,8 @@ def traceroute_handler(job: Job, job_host: Any) -> None: if len(arg_opt) > 0: arg_opt = traceroute_options_filter(arg_opt) - job_host.cmd(f"traceroute -n {arg_opt} {arg_ip}") + cmd = f"traceroute -n {arg_opt} {arg_ip}" + run_command(job, job_host, cmd) def ip_addr_add_handler(job: Job, job_host: Any) -> None: @@ -315,9 +415,15 @@ def ip_addr_add_handler(job: Job, job_host: Any) -> None: arg_dev = job.arg_1 if not ip_addr_add_checker(arg_ip, arg_mask, arg_dev): + # Log skipping ip addr add due to invalid args + logger.error( + "Ip addr add skipped", + extra={"dev": arg_dev, "ip": arg_ip, "mask": arg_mask}, + ) return - job_host.cmd(f"ip addr add {arg_ip}/{arg_mask} dev {arg_dev}") + cmd = f"ip addr add {arg_ip}/{arg_mask} dev {arg_dev}" + run_command(job, job_host, cmd) def iptables_handler(job: Job, job_host: Any) -> None: @@ -328,7 +434,8 @@ def iptables_handler(job: Job, job_host: Any) -> None: if not net_dev_checker(arg_dev): return - job_host.cmd(f"iptables -t nat -A POSTROUTING -o {arg_dev} -j MASQUERADE") + cmd = f"iptables -t nat -A POSTROUTING -o {arg_dev} -j MASQUERADE" + run_command(job, job_host, cmd) def port_forwarding_tcp_handler(job: Job, job_host: Any) -> None: @@ -342,9 +449,8 @@ def port_forwarding_tcp_handler(job: Job, job_host: Any) -> None: if not port_forwarding_checker(arg_iface, arg_port, arg_dest_addr, arg_dest_port): return - job_host.cmd( - f"iptables -t nat -A PREROUTING -p tcp -i {arg_iface} --dport {arg_port} -j DNAT --to-destination {arg_dest_addr}:{arg_dest_port}" - ) + cmd = f"iptables -t nat -A PREROUTING -p tcp -i {arg_iface} --dport {arg_port} -j DNAT --to-destination {arg_dest_addr}:{arg_dest_port}" + run_command(job, job_host, cmd) def port_forwarding_udp_handler(job: Job, job_host: Any) -> None: @@ -358,9 +464,8 @@ def port_forwarding_udp_handler(job: Job, job_host: Any) -> None: if not port_forwarding_checker(arg_iface, arg_port, arg_dest_addr, arg_dest_port): return - job_host.cmd( - f"iptables -t nat -A PREROUTING -p udp -i {arg_iface} --dport {arg_port} -j DNAT --to-destination {arg_dest_addr}:{arg_dest_port}" - ) + cmd = f"iptables -t nat -A PREROUTING -p udp -i {arg_iface} --dport {arg_port} -j DNAT --to-destination {arg_dest_addr}:{arg_dest_port}" + run_command(job, job_host, cmd) def ip_route_add_handler(job: Job, job_host: Any) -> None: @@ -372,7 +477,8 @@ def ip_route_add_handler(job: Job, job_host: Any) -> None: if not ip_route_add_checker(arg_ip, arg_mask, arg_router): return - job_host.cmd(f"ip route add {arg_ip}/{arg_mask} via {arg_router}") + cmd = f"ip route add {arg_ip}/{arg_mask} via {arg_router}" + run_command(job, job_host, cmd) def block_tcp_udp_port(job: Job, job_host: Any) -> None: @@ -381,9 +487,10 @@ def block_tcp_udp_port(job: Job, job_host: Any) -> None: if not valid_port(arg_port): return - - job_host.cmd(f"iptables -A INPUT -p tcp --dport {arg_port} -j DROP") - job_host.cmd(f"iptables -A INPUT -p udp --dport {arg_port} -j DROP") + cmd = f"iptables -A INPUT -p tcp --dport {arg_port} -j DROP" + run_command(job, job_host, cmd) + cmd = f"iptables -A INPUT -p udp --dport {arg_port} -j DROP" + run_command(job, job_host, cmd) def open_tcp_server_handler(job: Job, job_host: Any) -> None: @@ -394,9 +501,8 @@ def open_tcp_server_handler(job: Job, job_host: Any) -> None: if not valid_port(arg_port) or not valid_ip(arg_ip): return - job_host.cmd( - f"nohup nc -k -d {arg_ip} -l {arg_port} > /tmp/tcpserver 2>&1 < /dev/null &" - ) + cmd = f"nohup nc -k -d {arg_ip} -l {arg_port} > /tmp/tcpserver 2>&1 < /dev/null &" + run_command(job, job_host, cmd) def open_udp_server_handler(job: Job, job_host: Any) -> None: @@ -407,9 +513,8 @@ def open_udp_server_handler(job: Job, job_host: Any) -> None: if not valid_ip(arg_ip) or not valid_port(arg_port): return - job_host.cmd( - f"nohup nc -d -u {arg_ip} -l {arg_port} > /tmp/udpserver 2>&1 < /dev/null &" - ) + cmd = f"nohup nc -d -u {arg_ip} -l {arg_port} > /tmp/udpserver 2>&1 < /dev/null &" + run_command(job, job_host, cmd) def arp_handler(job: Job, job_host: Any) -> None: @@ -420,7 +525,8 @@ def arp_handler(job: Job, job_host: Any) -> None: if not valid_ip(arg_ip) or not valid_mac(arg_mac): return - job_host.cmd(f"arp -s {arg_ip} {arg_mac}") + cmd = f"arp -s {arg_ip} {arg_mac}" + run_command(job, job_host, cmd) def subinterface_with_vlan(job: Job, job_host: Any) -> None: @@ -436,11 +542,12 @@ def subinterface_with_vlan(job: Job, job_host: Any) -> None: ): return - job_host.cmd( - f"ip link add link {arg_intf} name {arg_intf_name}.{arg_vlan} type vlan id {arg_vlan}" - ) - job_host.cmd(f"ip addr add {arg_ip}/{arg_mask} dev {arg_intf_name}.{arg_vlan}") - job_host.cmd(f"ip link set dev {arg_intf_name}.{arg_vlan} up") + cmd = f"ip link add link {arg_intf} name {arg_intf_name}.{arg_vlan} type vlan id {arg_vlan}" + run_command(job, job_host, cmd) + cmd = f"ip addr add {arg_ip}/{arg_mask} dev {arg_intf_name}.{arg_vlan}" + run_command(job, job_host, cmd) + cmd = f"ip link set dev {arg_intf_name}.{arg_vlan} up" + run_command(job, job_host, cmd) def add_ipip_interface(job: Job, job_host: Any) -> None: @@ -451,12 +558,22 @@ def add_ipip_interface(job: Job, job_host: Any) -> None: arg_name_int = job.arg_4 if not ipip_interface_checker(arg_ip_start, arg_ip_end, arg_ip_int, arg_name_int): + # Log skipping IPIP creation due to invalid args + logger.error( + "Ipip interface, invalid params", + extra={ + "ip_start": arg_ip_start, + "ip_end": arg_ip_end, + "ip_int": arg_ip_int, + "name": arg_name_int, + }, + ) return - job_host.cmd( - f"ip tunnel add {arg_name_int} mode ipip remote {arg_ip_end} local {arg_ip_start}" - ) - job_host.cmd(f"ifconfig {arg_name_int} {arg_ip_int}") + cmd = f"ip tunnel add {arg_name_int} mode ipip remote {arg_ip_end} local {arg_ip_start}" + run_command(job, job_host, cmd) + cmd = f"ifconfig {arg_name_int} {arg_ip_int}" + run_command(job, job_host, cmd) def add_gre(job: Job, job_host: Any) -> None: @@ -468,11 +585,12 @@ def add_gre(job: Job, job_host: Any) -> None: if not add_gre_checker(arg_ip_start, arg_ip_end, arg_ip_iface, arg_name_iface): return - job_host.cmd( - f"ip tunnel add {arg_name_iface} mode gre remote {arg_ip_end} local {arg_ip_start} ttl 255" - ) - job_host.cmd(f"ip addr add {arg_ip_iface}/24 dev {arg_name_iface}") - job_host.cmd(f"ip link set {arg_name_iface} up") + cmd = f"ip tunnel add {arg_name_iface} mode gre remote {arg_ip_end} local {arg_ip_start} ttl 255" + run_command(job, job_host, cmd) + cmd = f"ip addr add {arg_ip_iface}/24 dev {arg_name_iface}" + run_command(job, job_host, cmd) + cmd = f"ip link set {arg_name_iface} up" + run_command(job, job_host, cmd) def arp_proxy_enable(job: Job, job_host: Any) -> None: @@ -482,25 +600,26 @@ def arp_proxy_enable(job: Job, job_host: Any) -> None: if not valid_iface(arg_iface): return - job_host.cmd(f"sysctl -w net.ipv4.conf.{arg_iface}.proxy_arp=1") + cmd = f"sysctl -w net.ipv4.conf.{arg_iface}.proxy_arp=1" + run_command(job, job_host, cmd) def dhcp_client(job: Job, job_host): info(f"[dhcp_client] host={job_host.name} iface={job.arg_1}") - out_ifconfig = job_host.cmd(f"ifconfig {job.arg_1} 0") + out_ifconfig = run_command(job, job_host, f"ifconfig {job.arg_1} 0") info(f"[dhcp_client] ifconfig {job.arg_1} 0 -> {out_ifconfig!r}") - out_rm = job_host.cmd("rm -f /var/lib/dhcp/dhclient.leases") + out_rm = run_command(job, job_host, "rm -f /var/lib/dhcp/dhclient.leases") info(f"[dhcp_client] rm leases -> {out_rm!r}") - job_host.cmd("echo 'initial-interval 6;' > /tmp/dhclient.conf") + run_command(job, job_host, "echo 'initial-interval 6;' > /tmp/dhclient.conf") dhclient_cmd = ( f"timeout -k 1 5 dhclient -d -v -4 -cf /tmp/dhclient.conf {job.arg_1} && " "ip route show && rm -f /tmp/dhclient.conf" ) info(f"[dhcp_client] running: {dhclient_cmd}") - out = job_host.cmd(dhclient_cmd) + out = run_command(job, job_host, dhclient_cmd) info(f"[dhcp_client] dhclient output:\n{out}") # Log resulting IP configuration - out_ip = job_host.cmd(f"ip addr show {job.arg_1}") + out_ip = run_command(job, job_host, f"ip addr show {job.arg_1}") info(f"[dhcp_client] ip addr after dhclient:\n{out_ip}") @@ -526,7 +645,7 @@ def dhcp_server(job: Job, job_host): # Log the generated dnsmasq config so we can inspect it in CI try: cfg_file = daemon.cfg_filenames[0] - cfg_content = job_host.cmd(f"cat {cfg_file}") + cfg_content = run_command(job, job_host, f"cat {cfg_file}") info(f"[dhcp_server] dnsmasq config ({cfg_file}):\n{cfg_content}") except Exception as e: info(f"[dhcp_server] could not read dnsmasq config: {e}") @@ -595,4 +714,18 @@ def strategy(self, job_id: int) -> None: self._strategy = self._dct[job_id] def handler(self) -> None: - self._strategy(self._job, self._job_host) + job_id = getattr(self._job, "job_id", None) + host_id = getattr(self._job, "host_id", None) + # Log job start + logger.debug("Job start", extra={"job_id": job_id, "host_id": host_id}) + try: + self._strategy(self._job, self._job_host) + # Log job success + logger.debug("Job done", extra={"job_id": job_id, "host_id": host_id}) + except Exception as e: + # Log job failure + logger.error( + "Job failed", + extra={"job_id": job_id, "host_id": host_id, "error": str(e)}, + ) + raise diff --git a/back/src/logging_config.py b/back/src/logging_config.py new file mode 100644 index 00000000..29de3cdd --- /dev/null +++ b/back/src/logging_config.py @@ -0,0 +1,109 @@ +import json +import logging +import os +from datetime import datetime, timezone +import requests +from dotenv import load_dotenv + +load_dotenv() + +LOG_LEVEL = os.getenv("LOG_LEVEL", "INFO").upper() +if os.getenv("MODE") == "dev": + UNIFIED_AGENT_URL = "http://localhost" +else: + UNIFIED_AGENT_URL = os.getenv("UNIFIED_AGENT_URL", "http://localhost") +HTTP_TIMEOUT = float(os.getenv("LOG_HTTP_TIMEOUT", "1.0")) +CELERY_LOG_GROUP = os.getenv("CELERY_LOG_GROUP", "") + +# Keys present on every LogRecord; used to filter extras for JSON payload +_RESERVED = { + "name", + "msg", + "args", + "levelname", + "levelno", + "pathname", + "filename", + "module", + "exc_info", + "exc_text", + "stack_info", + "lineno", + "funcName", + "created", + "msecs", + "relativeCreated", + "thread", + "threadName", + "processName", + "process", + "message", +} + + +class JsonFormatter(logging.Formatter): + """Render log records as JSON with extras preserved.""" + + def convert_level(self, level: str) -> str: + """Yandex log groups use different names for log levels, so this function does the conversion.""" + if level == "NOTSET": + return "TRACE" + elif level == "WARNING": + return "WARN" + elif level == "CRITICAL": + return "FATAL" + else: + return level + + def format(self, record: logging.LogRecord) -> str: + extras = { + k: v + for k, v in record.__dict__.items() + if k not in _RESERVED and not k.startswith("_") + } + payload = { + "message": record.getMessage(), + "level": self.convert_level(record.levelname), + "logger": record.name, + "timestamp": datetime.fromtimestamp( + record.created, tz=timezone.utc + ).isoformat(), + "extra": {}, + } + if extras: + payload["extra"] = extras + if record.exc_info: + payload["exc_info"] = self.formatException(record.exc_info) + return json.dumps(payload, ensure_ascii=False) + + +class HttpPostHandler(logging.Handler): + """Send each log record to an HTTP endpoint.""" + + def __init__(self, url: str, timeout: float = 1.0): + super().__init__() + self.url = url + self.timeout = timeout + + def emit(self, record: logging.LogRecord) -> None: + try: + payload = self.format(record) + headers = { + "Content-Type": "application/json", + "log-group": CELERY_LOG_GROUP, + } + requests.post(self.url, data=payload, headers=headers, timeout=self.timeout) + print("log requested") + except Exception: + self.handleError(record) + + +def configure_logging(logger: logging.Logger): + logger.setLevel(logging.INFO) + + formatter = JsonFormatter() + + http_handler = HttpPostHandler(UNIFIED_AGENT_URL, timeout=HTTP_TIMEOUT) + http_handler.setLevel(LOG_LEVEL) + http_handler.setFormatter(formatter) + logger.addHandler(http_handler) diff --git a/back/src/network.py b/back/src/network.py index b5694333..39bdeeb9 100644 --- a/back/src/network.py +++ b/back/src/network.py @@ -1,15 +1,19 @@ +import logging import os import time - -import psutil from ipmininet.ipnet import IPNet from mininet.log import info -from net_utils.vlan import clean_bridges, setup_vlans -from net_utils.vxlan import setup_vtep_interfaces, teardown_vtep_bridges -from network_schema import Network +import psutil +import logging_config from network_topology import MiminetTopology +from network_schema import Network +from net_utils.vlan import setup_vlans, clean_bridges +from net_utils.vxlan import setup_vtep_interfaces, teardown_vtep_bridges from psutil import Process +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) + class MiminetNetwork(IPNet): def __init__(self, topo: MiminetTopology, network: Network): @@ -54,10 +58,26 @@ def __check_files(self): if not os.path.exists(pcap_out_file1): self.__clear_files() + logger.error( + "Pcap out file isn't found", + extra={ + "task_id": getattr(self, "task_id", None), + "interface": link1, + "expected_file": pcap_out_file1, + }, + ) raise ValueError(f"No capture for interface '{link1}'.") if not os.path.exists(pcap_out_file2): self.__clear_files() + logger.error( + "Pcap file isn't found", + extra={ + "task_id": getattr(self, "task_id", None), + "interface": link2, + "expected_file": pcap_out_file2, + }, + ) raise ValueError(f"No capture for interface '{link2}'.") def __clear_files(self): @@ -83,13 +103,22 @@ def __clean_services(self): current_process = Process() children = current_process.children(recursive=True) allowed = ("mimidump", "bash") + killed_count = 0 + zombie_count = 0 for child in children: if child.status() == psutil.STATUS_ZOMBIE: # in case we already have zombies child.wait() + zombie_count += 1 elif child.name() not in allowed: # finish other processes info(f"Killed: {child.name()} {child.pid}") child.kill() child.wait() + killed_count += 1 + if zombie_count > 0 or killed_count > 0: + logger.warning( + "Cleanup is incomplete", + extra={"killed_processes": killed_count, "zombies_left": zombie_count}, + ) diff --git a/back/src/network_topology.py b/back/src/network_topology.py index a0b71caf..926acacd 100644 --- a/back/src/network_topology.py +++ b/back/src/network_topology.py @@ -7,6 +7,12 @@ from ipmininet.router.config import RouterConfig from network_schema import Network, Node, NodeConfig, NodeInterface from pkt_parser import is_ipv4_address +import logging +import logging_config + +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) +logger.setLevel(logging.DEBUG) class MiminetTopology(IPTopo): @@ -126,6 +132,15 @@ def build(self, *args, **kwargs): links = [] interfaces = [] + logger.info( + "Topology build started", + extra={ + "event": "topology_build_start", + "nodes_count": len(self.__network.nodes), + "edges_count": len(self.__network.edges), + }, + ) + for node in self.__network.nodes: # Caches node by ID for quick lookup later self.__id_to_node[node.data.id] = node @@ -158,7 +173,6 @@ def _to_percent(val): raise ValueError( f"Edge '{edge_id}' references unknown target node '{target_id}'." ) - # Mininet host objects (https://mininet.org/api/classmininet_1_1node_1_1Host.html) src_host = self.__nodes[source_id] trg_host = self.__nodes[target_id] @@ -193,6 +207,18 @@ def _to_percent(val): duplicate_percentage=duplicate_percentage, ) + logger.debug( + "Link created", + extra={ + "event": "link_created", + "edge_id": edge_id, + "link1": str(link1), + "link2": str(link2), + "src_iface": src_iface.name, + "trg_iface": trg_iface.name, + }, + ) + self.__configure_link(link1[src_host], src_iface) self.__configure_link(link2[trg_host], trg_iface) @@ -203,6 +229,18 @@ def _to_percent(val): interfaces.append(trg_iface.name) if links: + logger.debug( + "Network capture setup", + extra={ + "event": "capture_setup", + "interfaces": interfaces, + "links": [str(link) for link in links], + "options": { + "base_filename": "capture", + "extra_arguments": "not igmp", + }, + }, + ) # Set up packet capturing self.addNetworkCapture( nodes=[], @@ -210,6 +248,13 @@ def _to_percent(val): base_filename="capture", extra_arguments="not igmp", ) + logger.info( + "Topology build completed", + extra={ + "event": "topology_build_end", + "interfaces": self.__iface_pairs.copy(), + }, + ) super().build(*args, **kwargs) def addLink( diff --git a/back/src/tasks.py b/back/src/tasks.py index afefd08f..abab7175 100644 --- a/back/src/tasks.py +++ b/back/src/tasks.py @@ -1,16 +1,20 @@ import json import os import signal - +import logging +import logging_config import marshmallow_dataclass from celery_app import ( SEND_NETWORK_RESPONSE_EXCHANGE, SEND_NETWORK_RESPONSE_ROUTING_KEY, app, ) -from emulator import emulate -from mininet.log import error, setLogLevel +from mininet.log import setLogLevel from network_schema import Network +from emulator import emulate + +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) def run_miminet(network_json: str): @@ -34,7 +38,7 @@ def run_miminet(network_json: str): network_schema = marshmallow_dataclass.class_schema(Network)() network_json = network_schema.load(jnet, unknown="include") - for _ in range(4): + for attempt in range(4): try: animation, pcaps = emulate(network_json) @@ -42,7 +46,14 @@ def run_miminet(network_json: str): except Exception as e: # Sometimes mininet doesn't work correctly and simulation needs to be redone, # Example of mininet error: https://github.com/mininet/mininet/issues/737. - error(e) + logger.warning( + "Emulating retry", + extra={ + "task_id": None, + "attempt": attempt + 1, + "error": str(e), + }, + ) continue return "[]", [] diff --git a/front/.env b/front/.env index 6df934b1..6d0bea1c 100755 --- a/front/.env +++ b/front/.env @@ -31,5 +31,4 @@ REFRESH_TOKEN_EXPIRES=12 # YANDEX_POSTGRES_DB=miminet # YANDEX_POSTGRES_SSLMODE=verify-full -# Режим работы: dev (локальный PostgreSQL) или prod (Yandex Cloud PostgreSQL) -MODE=dev \ No newline at end of file +MIMINET_LOG_GROUP="e23bdqg95gpneolg1il8" diff --git a/front/docker-compose-prod.yml b/front/docker-compose-prod.yml index d7c29e6f..0ab12c4c 100644 --- a/front/docker-compose-prod.yml +++ b/front/docker-compose-prod.yml @@ -13,6 +13,7 @@ services: rabbitmq_network: env_file: - .env + - ../.env expose: - 80 volumes: @@ -58,6 +59,7 @@ services: restart: always env_file: - .env + - ../.env volumes: - ./default.conf.template:/etc/nginx/templates/default.conf.template ports: diff --git a/front/docker-compose.yml b/front/docker-compose.yml index 63d65ba8..a36763dc 100644 --- a/front/docker-compose.yml +++ b/front/docker-compose.yml @@ -13,6 +13,7 @@ services: rabbitmq_network: env_file: - .env + - ../.env expose: - 80 volumes: @@ -61,6 +62,7 @@ services: restart: always env_file: - .env + - ../.env volumes: - ./default.conf.template:/etc/nginx/templates/default.conf.template ports: @@ -86,6 +88,7 @@ services: restart: unless-stopped env_file: - .env + - ../.env volumes: - pgdata:/var/lib/postgresql networks: diff --git a/front/rabbitmq/rabbitmq.conf b/front/rabbitmq/rabbitmq.conf index 1d53c1d4..724d5846 100644 --- a/front/rabbitmq/rabbitmq.conf +++ b/front/rabbitmq/rabbitmq.conf @@ -1,3 +1,5 @@ disk_free_limit.absolute = 536870912 log.file.level = info heartbeat = 60 +deprecated_features.permit.transient_nonexcl_queues = true +deprecated_features.permit.global_qos = true diff --git a/front/src/logging_config.py b/front/src/logging_config.py new file mode 100644 index 00000000..08b83c13 --- /dev/null +++ b/front/src/logging_config.py @@ -0,0 +1,109 @@ +import json +import logging +import os +from datetime import datetime, timezone +import requests +from dotenv import load_dotenv + +load_dotenv() + +LOG_LEVEL = os.getenv("LOG_LEVEL", "INFO").upper() +if os.getenv("MODE") == "dev": + UNIFIED_AGENT_URL = "http://localhost" +else: + UNIFIED_AGENT_URL = os.getenv("UNIFIED_AGENT_URL", "http://localhost") +HTTP_TIMEOUT = float(os.getenv("LOG_HTTP_TIMEOUT", "1.0")) +MIMINET_LOG_GROUP = os.getenv("MIMINET_LOG_GROUP", "") + +# Keys present on every LogRecord; used to filter extras for JSON payload +_RESERVED = { + "name", + "msg", + "args", + "levelname", + "levelno", + "pathname", + "filename", + "module", + "exc_info", + "exc_text", + "stack_info", + "lineno", + "funcName", + "created", + "msecs", + "relativeCreated", + "thread", + "threadName", + "processName", + "process", + "message", +} + + +class JsonFormatter(logging.Formatter): + """Render log records as JSON with extras preserved.""" + + def convert_level(self, level: str) -> str: + """Yandex log groups use different names for log levels, so this function does the conversion.""" + if level == "NOTSET": + return "TRACE" + elif level == "WARNING": + return "WARN" + elif level == "CRITICAL": + return "FATAL" + else: + return level + + def format(self, record: logging.LogRecord) -> str: + extras = { + k: v + for k, v in record.__dict__.items() + if k not in _RESERVED and not k.startswith("_") + } + payload = { + "message": record.getMessage(), + "level": self.convert_level(record.levelname), + "logger": record.name, + "timestamp": datetime.fromtimestamp( + record.created, tz=timezone.utc + ).isoformat(), + "extra": {}, + } + if extras: + payload["extra"] = extras + if record.exc_info: + payload["exc_info"] = self.formatException(record.exc_info) + return json.dumps(payload, ensure_ascii=False) + + +class HttpPostHandler(logging.Handler): + """Send each log record to an HTTP endpoint.""" + + def __init__(self, url: str, timeout: float = 1.0): + super().__init__() + self.url = url + self.timeout = timeout + + def emit(self, record: logging.LogRecord) -> None: + try: + payload = self.format(record) + headers = { + "Content-Type": "application/json", + "log-group": MIMINET_LOG_GROUP, + } + requests.post(self.url, data=payload, headers=headers, timeout=self.timeout) + print("log requested") + except Exception: + self.handleError(record) + + +def configure_logging(logger: logging.Logger): + logger.setLevel(logging.INFO) + + formatter = JsonFormatter() + + http_handler = HttpPostHandler(UNIFIED_AGENT_URL, timeout=HTTP_TIMEOUT) + http_handler.setLevel(LOG_LEVEL) + http_handler.setFormatter(formatter) + logger.addHandler(http_handler) diff --git a/front/src/miminet_network.py b/front/src/miminet_network.py index 25cd5378..a26b7d88 100644 --- a/front/src/miminet_network.py +++ b/front/src/miminet_network.py @@ -2,8 +2,9 @@ import json import os import shutil +import logging +import logging_config import uuid - from flask import ( flash, jsonify, @@ -21,6 +22,9 @@ PREVIEW_IMAGES_ROOT = "static/images/preview" +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) + def CORS_header(response): response.headers.add("Access-Control-Allow-Credentials", "true") @@ -584,6 +588,14 @@ def get_emulation_queue_size(): .count() ) + logger.info( + "Emulation queue size", + extra={ + "time_filter": time_filter_req, + "count": emulated_networks_count, + }, + ) + return make_response( jsonify({"size": emulated_networks_count}), 200, diff --git a/front/src/miminet_simulation.py b/front/src/miminet_simulation.py index f192cfd3..135dd70d 100644 --- a/front/src/miminet_simulation.py +++ b/front/src/miminet_simulation.py @@ -1,12 +1,16 @@ import os import uuid - +import logging +import logging_config from celery_app import EXCHANGE_TYPE, SEND_NETWORK_EXCHANGE, app from flask import jsonify, make_response, redirect, request, url_for from flask_jwt_extended import get_jwt_identity, jwt_required from miminet_model import Network, Simulate, SimulateLog, db from werkzeug.wrappers import Response +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) + @jwt_required() def run_simulation() -> Response: @@ -14,6 +18,15 @@ def run_simulation() -> Response: user_id = get_jwt_identity() network_guid = request.args.get("guid", type=str) + logger.info( + "Run simulation start", + extra={ + "user_id": getattr(user_id, "id", None), + "guid": network_guid, + "method": request.method, + }, + ) + if not network_guid: ret = { "simulation_id": -1, @@ -36,11 +49,18 @@ def run_simulation() -> Response: # Get saved emulations sims = Simulate.query.filter(Simulate.network_id == net.id).all() + removed = len(sims) + # Remove all previous emulations for s in sims: db.session.delete(s) db.session.commit() + logger.info( + "Run simulation cleanup", + extra={"network_id": net.id, "removed_sims": removed}, + ) + # Write log simlog = SimulateLog( author_id=net.author_id, network=net.network, network_guid=net.guid @@ -53,17 +73,49 @@ def run_simulation() -> Response: db.session.add(simlog) db.session.commit() - # Send emulation task to celery - app.send_task( - "tasks.mininet_worker", - (net.network,), - routing_key=str(uuid.uuid4()), - exchange=SEND_NETWORK_EXCHANGE, - exchange_type=EXCHANGE_TYPE, - task_id=str(task_guid), - headers={"network_task_name": "tasks.save_simulate_result"}, + logger.info( + "Run simulation created", + extra={ + "network_id": net.id, + "simulation_id": sim.id, + "task_guid": str(task_guid), + }, ) + # Send emulation task to celery + routing_key = str(uuid.uuid4()) + try: + app.send_task( + "tasks.mininet_worker", + (net.network,), + routing_key=routing_key, + exchange=SEND_NETWORK_EXCHANGE, + exchange_type=EXCHANGE_TYPE, + task_id=str(task_guid), + headers={"network_task_name": "tasks.save_simulate_result"}, + ) + logger.info( + "Run simulation enqueued", + extra={ + "simulation_id": sim.id, + "task_guid": str(task_guid), + "routing_key": routing_key, + "exchange": SEND_NETWORK_EXCHANGE.name, + }, + ) + except Exception as e: + logger.error( + "Run simulation enqueue failed", + extra={ + "simulation_id": sim.id, + "task_guid": str(task_guid), + "routing_key": routing_key, + "exchange": SEND_NETWORK_EXCHANGE.name, + "error": str(e), + }, + ) + raise + # Return network id to check emulation result ret = {"simulation_id": sim.id} return make_response(jsonify(ret), 201) diff --git a/front/src/quiz/service/check_practice_service.py b/front/src/quiz/service/check_practice_service.py index 1771b077..2f2bb931 100644 --- a/front/src/quiz/service/check_practice_service.py +++ b/front/src/quiz/service/check_practice_service.py @@ -1,9 +1,13 @@ import ipaddress import logging - +import logging_config import quiz.service.check_host_service as chs from quiz.service.check_network_service import check_network_configuration +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) +logger.setLevel(logging.DEBUG) + def check_in_one_network_with(requirement, answer, device): points = 0 @@ -11,6 +15,15 @@ def check_in_one_network_with(requirement, answer, device): target_id = requirement.get("target") points_awarded = requirement.get("points", 1) + # Log start of in_one_network_with check + logger.debug( + "In one network with, start", + extra={ + "device": device, + "target": target_id, + "points_awarded": points_awarded, + }, + ) if not target_id: hints.append("Целевое устройство не указано.") @@ -49,9 +62,28 @@ def get_networks(node): for net2 in target_networks: if net1.overlaps(net2): points = points_awarded + logger.info( + "In one network with, success", + extra={ + "device": device, + "target": target_id, + "network": str(net1), + "awarded": points, + }, + ) return points, hints hints.append(f"{device} и {target_id} не находятся в одной сети.") + # Log failure to be in same network and awarded points (usually 0) + logger.info( + "In one network with, fail", + extra={ + "device": device, + "target": target_id, + "awarded": points, + "hints": hints, + }, + ) return points, hints @@ -62,6 +94,17 @@ def check_abstract_ip_equal(abstract_equal, answer, device): if not abstract_equal: return points, hints + # Log parameters before abstract IP equality check + logger.debug( + "Abstract ip equal, start", + extra={ + "device": device, + "to": abstract_equal.get("to"), + "expected_equal_with": abstract_equal.get("expected_equal_with"), + "points_awarded": abstract_equal.get("points", 1), + }, + ) + nodes = answer["nodes"] edges = answer["edges"] @@ -111,6 +154,17 @@ def check_abstract_ip_equal(abstract_equal, answer, device): common_ips = device_ips_to_to_node.intersection(compare_ips) if common_ips: points = max(points_awarded, 0) + # Log successful abstract IP equality and awarded points + logger.info( + "Abstract ip equal, success", + extra={ + "device": device, + "to": to_node_id, + "compare": expected_equal_with, + "common_ips": list(common_ips), + "awarded": points, + }, + ) else: hints.append( f"IP-адреса интерфейсов {device}, направленных к {to_node_id}, не совпадают ни с одним IP-адресом интерфейсов {expected_equal_with}." @@ -118,6 +172,17 @@ def check_abstract_ip_equal(abstract_equal, answer, device): if points_awarded < 0: points = points_awarded + # Log final abstract IP equality result and hints + logger.info( + "Abstract ip equal result", + extra={ + "device": device, + "to": to_node_id, + "compare": expected_equal_with, + "awarded": points, + "hints": hints, + }, + ) return points, hints @@ -134,20 +199,48 @@ def check_host(requirement, answer, device): hints.append(f"Устройство {device} не найдено в сети.") return points_for_host, hints + # Log start of host check and requirement keys + logger.debug( + "Practice check host start", + extra={"device": device, "requirement_keys": list(requirement.keys())}, + ) + # Checking commands (ping in particular) cmd = requirement.get("cmd") if cmd: + # Log command check input + logger.debug("Practice cmd check", extra={"device": device, "cmd": cmd}) points_for_cmd, cmd_hints = chs.process_host_command(cmd, answer, device) points_for_host += points_for_cmd hints.extend(cmd_hints) + # Log command check result and awarded points + logger.info( + "Practice cmd result", + extra={ + "device": device, + "awarded": points_for_cmd, + "host_total": points_for_host, + "hints": cmd_hints, + }, + ) # Checking for identical VLANs all_vlan_conditions_passed = True + equal_vlan_hints_all = [] + equal_vlan_targets = [] equal_vlan_id = requirement.get("equal_vlan_id") if equal_vlan_id: targets = equal_vlan_id.get("targets", []) - points = equal_vlan_id.get("points", 1) + equal_vlan_targets = targets + equal_vlan_points = equal_vlan_id.get("points", 1) + # Log VLAN equality check input + logger.debug( + "Practice equal vlan check", + extra={"device": device, "targets": targets, "points": equal_vlan_points}, + ) + + equal_vlan_hints_all = [] for target in targets: result, equal_vlan_hints = chs.check_vlan_id( @@ -156,18 +249,46 @@ def check_host(requirement, answer, device): if not result: all_vlan_conditions_passed = False hints.extend(equal_vlan_hints) + equal_vlan_hints_all.extend(equal_vlan_hints) + equal_vlan_awarded = ( + equal_vlan_points if all_vlan_conditions_passed and equal_vlan_id else 0 + ) if all_vlan_conditions_passed: - points_for_host += points - points = 0 + points_for_host += equal_vlan_points + # Log VLAN equality result and points + logger.info( + "Practice equal vlan result", + extra={ + "device": device, + "targets": equal_vlan_targets, + "awarded": equal_vlan_awarded, + "host_total": points_for_host, + "hints": equal_vlan_hints_all if not all_vlan_conditions_passed else [], + }, + ) # Checking for different VLANs all_vlan_conditions_passed = True + no_equal_vlan_hints_all = [] + no_equal_vlan_targets = [] no_equal_vlan_id = requirement.get("no_equal_vlan_id") if no_equal_vlan_id: targets = no_equal_vlan_id.get("targets", []) - points = no_equal_vlan_id.get("points", 1) + no_equal_vlan_targets = targets + no_equal_vlan_points = no_equal_vlan_id.get("points", 1) + # Log VLAN inequality check input + logger.debug( + "Practice no equal vlan check", + extra={ + "device": device, + "targets": targets, + "points": no_equal_vlan_points, + }, + ) + + no_equal_vlan_hints_all = [] for target in targets: result, no_equal_vlan_hints = chs.check_vlan_id( @@ -176,15 +297,38 @@ def check_host(requirement, answer, device): if not result: all_vlan_conditions_passed = False hints.extend(no_equal_vlan_hints) + no_equal_vlan_hints_all.extend(no_equal_vlan_hints) + no_equal_vlan_awarded = ( + no_equal_vlan_points if all_vlan_conditions_passed and no_equal_vlan_id else 0 + ) if all_vlan_conditions_passed: - points_for_host += points + points_for_host += no_equal_vlan_points + # Log VLAN inequality result and points + logger.info( + "Practice no equal vlan result", + extra={ + "device": device, + "targets": no_equal_vlan_targets, + "awarded": no_equal_vlan_awarded, + "host_total": points_for_host, + "hints": no_equal_vlan_hints_all if not all_vlan_conditions_passed else [], + }, + ) # Checking for the privacy of an IP address ip_check = requirement.get("ip_check") if ip_check: points = ip_check.get("points", 1) target_node_id = ip_check.get("to") + # Log IP privacy check input + logger.debug( + "Practice ip check", + extra={"device": device, "target": target_node_id, "points": points}, + ) + + ip_check_hints = [] + before = points_for_host target_node = next( (node for node in nodes if node["data"]["id"] == target_node_id), None @@ -194,6 +338,9 @@ def check_host(requirement, answer, device): hints.append( f"Целевое устройство {target_node_id} для проверки приватности ip-адреса не найдено в сети." ) + ip_check_hints.append( + f"Целевое устройство {target_node_id} для проверки приватности ip-адреса не найдено в сети." + ) for interface in host_node.get("interface", []): edge_id = interface.get("connect") @@ -202,6 +349,9 @@ def check_host(requirement, answer, device): hints.append( f"Интерфейс на устройстве {device} не подключен к {target_node_id}." ) + ip_check_hints.append( + f"Интерфейс на устройстве {device} не подключен к {target_node_id}." + ) continue connected_edge = next( @@ -213,6 +363,9 @@ def check_host(requirement, answer, device): hints.append( f"Соединение для интерфейса на устройстве {device} не найдено." ) + ip_check_hints.append( + f"Соединение для интерфейса на устройстве {device} не найдено." + ) continue connected_node_id = ( @@ -230,16 +383,47 @@ def check_host(requirement, answer, device): hints.append( f"IP-адрес {source_ip} на устройстве {device} не является приватным." ) + ip_check_hints.append( + f"IP-адрес {source_ip} на устройстве {device} не является приватным." + ) else: hints.append( f"Устройство {device} не подключено к {target_node_id}. Проверка приватности IP-адреса невозможна." ) + ip_check_hints.append( + f"Устройство {device} не подключено к {target_node_id}. Проверка приватности IP-адреса невозможна." + ) + awarded_ip_check = points_for_host - before + # Log IP privacy check result and points + logger.info( + "Practice ip check result", + extra={ + "device": device, + "target": target_node_id, + "awarded": awarded_ip_check, + "host_total": points_for_host, + "hints": ip_check_hints, + }, + ) # Checking whether the default gateway is configured required_default_gw = requirement.get("default_gw") if required_default_gw: points = required_default_gw.get("points", 1) actual_default_gw = host_node["config"].get("default_gw") + # Log default gateway absence check input + logger.debug( + "Practice default gw check", + extra={ + "device": device, + "expected_absent": True, + "actual": actual_default_gw, + "points": points, + }, + ) + + default_gw_hints = [] + before = points_for_host if not actual_default_gw: points_for_host += points @@ -247,6 +431,20 @@ def check_host(requirement, answer, device): hints.append( f"Вы настроили маршрут по умолчанию ({actual_default_gw}) у {device}, но по условию задания это не требовалось." ) + default_gw_hints.append( + f"Вы настроили маршрут по умолчанию ({actual_default_gw}) у {device}, но по условию задания это не требовалось." + ) + awarded_default_gw = points_for_host - before + # Log default gateway check result and points + logger.info( + "Practice default gw result", + extra={ + "device": device, + "awarded": awarded_default_gw, + "host_total": points_for_host, + "hints": default_gw_hints, + }, + ) # Mask check mask_check = requirement.get("mask_check") @@ -254,17 +452,38 @@ def check_host(requirement, answer, device): points = mask_check.get("points", 1) target = mask_check.get("to") expected_mask = mask_check.get("subnet_mask") + # Log subnet mask check input + logger.debug( + "Practice mask check", + extra={ + "device": device, + "target": target, + "expected_mask": expected_mask, + "points": points, + }, + ) result, mask_hints = chs.check_subnet_mask( answer, device, target, expected_mask ) + awarded_mask = 0 if result: points_for_host += points + awarded_mask = points else: hints.extend(mask_hints) - - ip_equal = requirement.get("ip_equal") + # Log subnet mask check result and points + logger.info( + "Practice mask check result", + extra={ + "device": device, + "target": target, + "awarded": awarded_mask, + "host_total": points_for_host, + "hints": mask_hints if not result else [], + }, + ) # Check for a specific IP address ip_equal = requirement.get("ip_equal") @@ -272,8 +491,19 @@ def check_host(requirement, answer, device): points = ip_equal.get("points", 1) expected_ip = ip_equal.get("expected_ip") target_node_id = ip_equal.get("to") + # Log specific IP check input + logger.debug( + "Practice ip equal check", + extra={ + "device": device, + "target": target_node_id, + "expected_ip": expected_ip, + "points": points, + }, + ) found = False + ip_equal_hints = [] for interface in host_node.get("interface", []): edge_id = interface.get("connect") @@ -304,11 +534,30 @@ def check_host(requirement, answer, device): hints.append( f"IP-адрес интерфейса на устройстве {device}, подключенного к {target_node_id}, должен быть {expected_ip}, но найден {actual_ip}." ) + ip_equal_hints.append( + f"IP-адрес интерфейса на устройстве {device}, подключенного к {target_node_id}, должен быть {expected_ip}, но найден {actual_ip}." + ) if not found: hints.append( f"Не найден интерфейс на устройстве {device}, подключённый к {target_node_id} с IP {expected_ip}." ) + ip_equal_hints.append( + f"Не найден интерфейс на устройстве {device}, подключённый к {target_node_id} с IP {expected_ip}." + ) + + # Log specific IP check result and points + logger.info( + "Practice ip equal result", + extra={ + "device": device, + "target": target_node_id, + "expected_ip": expected_ip, + "awarded": points if found else 0, + "host_total": points_for_host, + "hints": ip_equal_hints, + }, + ) # abstract_ip_equal abstract_equal = requirement.get("abstract_ip_equal") @@ -316,6 +565,16 @@ def check_host(requirement, answer, device): points, abstract_hints = check_abstract_ip_equal(abstract_equal, answer, device) points_for_host += points hints.extend(abstract_hints) + # Log abstract IP equality aggregation result + logger.info( + "Practice abstract ip equal result", + extra={ + "device": device, + "awarded": points, + "host_total": points_for_host, + "hints": abstract_hints, + }, + ) # Check if two hosts are in the same network in_one_network_with = requirement.get("in_one_network_with") @@ -323,6 +582,26 @@ def check_host(requirement, answer, device): p, net_hints = check_in_one_network_with(in_one_network_with, answer, device) points_for_host += p hints.extend(net_hints) + # Log same-network check result and points + logger.info( + "Practice in one network result", + extra={ + "device": device, + "awarded": p, + "host_total": points_for_host, + "hints": net_hints, + }, + ) + + # Log host-level summary: points and hints count + logger.info( + "Practice check host done", + extra={ + "device": device, + "host_total": points_for_host, + "hints_count": len(hints), + }, + ) return points_for_host, hints @@ -330,11 +609,26 @@ def check_host(requirement, answer, device): def check_task(requirements, answer): total_points = 0 hints = [] - - logging.info(f"requirements: {requirements}") + # Log task-level start: counts of requirements/nodes/edges + logger.info( + "Practice check task start", + extra={ + "requirements_count": len(requirements), + "nodes_count": len(answer.get("nodes", [])), + "edges_count": len(answer.get("edges", [])), + }, + ) for requirement in requirements: for device, requirements in requirement.items(): + # Log device requirement keys before processing + logger.debug( + "Practice check task device", + extra={ + "device": device, + "requirements_keys": list(requirements.keys()), + }, + ) if ( device.startswith("host") or device.startswith("server") @@ -343,11 +637,36 @@ def check_task(requirements, answer): points, device_hints = check_host(requirements, answer, device) total_points += points hints.extend(device_hints) + # Log device result: points and hints + logger.info( + "Practice device result", + extra={ + "device": device, + "awarded": points, + "total_points": total_points, + "hints": device_hints, + }, + ) elif device.startswith("network"): points, network_hints = check_network_configuration( requirements, answer ) total_points += points hints.extend(network_hints) + # Log network result: points and hints + logger.info( + "Practice network result", + extra={ + "network": device, + "awarded": points, + "total_points": total_points, + "hints": network_hints, + }, + ) + # Log task-level summary: total points and hints count + logger.info( + "Practice check task done", + extra={"total_points": total_points, "hints_count": len(hints)}, + ) return total_points, hints diff --git a/front/src/tasks.py b/front/src/tasks.py index 24fbf1ce..14b08ea3 100644 --- a/front/src/tasks.py +++ b/front/src/tasks.py @@ -1,9 +1,10 @@ import json -import logging import os import shutil import uuid - +import logging +import logging_config +from sqlalchemy.orm.exc import StaleDataError from app import app as flask_app from celery.exceptions import TimeoutError from celery.result import AsyncResult, allow_join_result @@ -13,7 +14,9 @@ answer_on_exam_question, answer_on_exam_without_session, ) -from sqlalchemy.orm.exc import StaleDataError + +logger = logging.getLogger(__name__) +logging_config.configure_logging(logger) @app.task(bind=True, queue="common-results-queue") @@ -95,7 +98,10 @@ def perform_task_check(session_question_id, data_list): ) except Exception as e: - logging.error(f"Ошибка при создании задачи: {e}.") + logger.error( + "Check task emulation create failed", + extra={"error": str(e), "guid": guid}, + ) answer_on_exam_without_session(networks_to_check, guid) @@ -122,7 +128,13 @@ def perform_task_check(session_question_id, data_list): ) except Exception as e: - logging.error(f"Ошибка при создании задачи: {e}.") + logger.error( + "Check task emulation create failed", + extra={ + "error": str(e), + "session_question_id": session_question_id, + }, + ) with flask_app.app_context(): answer_on_exam_question(session_question_id, networks_to_check) @@ -135,13 +147,39 @@ def create_emulation_task(net_schema): net_schema = ( json.dumps(net_schema) if not isinstance(net_schema, str) else net_schema ) + routing_key = str(uuid.uuid4()) - async_obj = app.send_task( - "tasks.mininet_worker", - [net_schema], - routing_key=str(uuid.uuid4()), - exchange=SEND_NETWORK_EXCHANGE, - exchange_type=EXCHANGE_TYPE, + # Log start of sending task to RabbitMQ + logger.info( + "Rabbitmq send task start", + extra={"routing_key": routing_key, "exchange": SEND_NETWORK_EXCHANGE.name}, + ) + + try: + async_obj = app.send_task( + "tasks.mininet_worker", + [net_schema], + routing_key=routing_key, + exchange=SEND_NETWORK_EXCHANGE, + exchange_type=EXCHANGE_TYPE, + ) + except Exception as e: + # Log broker rejection (incl. disk_free_limit) + logger.error( + "Rabbitmq send task failed", + extra={ + "routing_key": routing_key, + "exchange": SEND_NETWORK_EXCHANGE.name, + "error": str(e), + "hint": "Check RabbitMQ disk_free_limit and broker availability", + }, + ) + raise + + # Log successful scheduling of task in queue + logger.info( + "Rabbitmq send task scheduled", + extra={"routing_key": routing_key, "task_id": async_obj.id}, ) async_res = AsyncResult(id=async_obj.id, app=app) @@ -150,7 +188,28 @@ def create_emulation_task(net_schema): with allow_join_result(): animation, _ = async_res.wait(timeout=120) + # Log successful result receipt from worker + logger.info( + "Rabbitmq receive result success", + extra={"routing_key": routing_key, "task_id": async_obj.id}, + ) return animation except TimeoutError: + # Log timeout while waiting for result + logger.error( + "Rabbitmq receive result timeout", + extra={"routing_key": routing_key, "task_id": async_obj.id}, + ) # TODO improve error message (add user info) raise Exception(f"""Check task failed!\nNetwork Schema: {net_schema}.""") + except Exception as e: + # Log any other errors while waiting for result + logger.error( + "Rabbitmq receive result failed", + extra={ + "routing_key": routing_key, + "task_id": async_obj.id, + "error": str(e), + }, + ) + raise