diff --git a/.github/workflows/integration-tests.yml b/.github/workflows/integration-tests.yml index 2ab0edf93d..538ab87ede 100644 --- a/.github/workflows/integration-tests.yml +++ b/.github/workflows/integration-tests.yml @@ -55,7 +55,7 @@ jobs: - name: Upload Artifacts if: always() - uses: actions/upload-artifact@v5 + uses: actions/upload-artifact@v6 with: # Replaces slashes with underscores for valid artifact naming name: ${{ github.run_id }}-${{ strategy.job-index }}-integration-output diff --git a/.github/workflows/unit-tests.yml b/.github/workflows/unit-tests.yml index 5a19ba3b3c..98427b1945 100644 --- a/.github/workflows/unit-tests.yml +++ b/.github/workflows/unit-tests.yml @@ -56,7 +56,7 @@ jobs: - name: Upload Artifacts if: always() - uses: actions/upload-artifact@v5 + uses: actions/upload-artifact@v6 with: name: test_slips-output-${{ strategy.job-index }} path: | diff --git a/.secrets.baseline b/.secrets.baseline index 42de85b9f8..86c4471ba3 100644 --- a/.secrets.baseline +++ b/.secrets.baseline @@ -149,7 +149,7 @@ "filename": "config/slips.yaml", "hashed_secret": "4cac50cee3ad8e462728e711eac3e670753d5016", "is_verified": false, - "line_number": 268 + "line_number": 278 } ], "dataset/test14-malicious-zeek-dir/http.log": [ @@ -7185,5 +7185,5 @@ } ] }, - "generated_at": "2026-03-02T22:46:58Z" + "generated_at": "2026-03-27T14:25:16Z" } diff --git a/AGENTS.md b/AGENTS.md new file mode 100644 index 0000000000..48cb9d39e9 --- /dev/null +++ b/AGENTS.md @@ -0,0 +1,42 @@ +# AGENTS.md + +## Project overview +- Entry point: `slips.py` (starts the main process, spawns modules, runs in interactive/daemon modes). +- Core framework code lives in `slips/`, `slips_files/`, and `managers/`. +- Detection/analysis modules are in `modules/` (implement the `IModule` interface). +- Configuration is in `config/` (main config: `config/slips.yaml`). +- Tests live under `tests/` (unit + integration suites). +- Documentation is in `docs/` (see `docs/contributing.md` for contribution workflow, branching, and PR expectations). +- UIs/tools: `SlipsWeb/`, `webinterface/`, `webinterface.sh`, and `kalipso.sh`. + +## Build and test commands +- Run locally (no build step): + - `./slips.py -e 1 -f dataset/test7-malicious.pcap -o output_dir` +- Build the Docker image (from `docs/installation.md`): + - `docker build --no-cache -t slips -f docker/Dockerfile .` + - If build networking fails: `docker build --network=host --no-cache -t slips -f docker/Dockerfile .` +- Run the Docker image: + - `docker run -it --rm --net=host slips` + +## Code style guidelines +- Python formatting is enforced via pre-commit: + - Black with `--line-length 79` (see `.pre-commit-config.yaml`). + - Ruff is used for linting and autofixes. +- Keep docstrings at the top of files where present (pre-commit `check-docstring-first`). +- Maintain clean whitespace (no trailing whitespace, final newline). +- Follow existing module patterns (`IModule` in `slips_files/common/abstracts/module.py`). + +## Testing instructions +- The canonical test runner is `tests/run_all_tests.sh` (runs unit tests then integration tests). +- Equivalent manual sequence (from `tests/run_all_tests.sh`): + - `./slips.py -cc` + - `printf "0" | ./slips.py -k` + - `python3 -m pytest tests/ --ignore="tests/integration_tests" -n 7 -p no:warnings -vvvv -s` + - `python3 tests/destrctor.py` + - `./slips.py -cc` + - `printf "0" | ./slips.py -k` + - `python3 -m pytest -s tests/integration_tests/test_portscans.py -p no:warnings -vv` + - `python3 -m pytest -s tests/integration_tests/test_dataset.py -p no:warnings -vv` + - `python3 -m pytest -s tests/integration_tests/test_config_files.py -p no:warnings -vv` + - `printf "0" | ./slips.py -k` + - `./slips.py -cc` diff --git a/config/slips.yaml b/config/slips.yaml index 5e307f143e..ec90717ac3 100644 --- a/config/slips.yaml +++ b/config/slips.yaml @@ -163,6 +163,16 @@ parameters: # client_ips : [10.0.0.1, 11.0.0.0/24] client_ips: [] +############################# +Debug: + # Generate latency, throughput, and other performance related CSV files and plots in output/performance_plots/ for debugging + # When enabled, Slips records extra per-flow/per-minute performance data from + # input, profiler workers, and evidence handling, then generates summary plots + # during shutdown. Keep this disabled for normal runs because it adds extra + # bookkeeping and disk writes. + # available options are true/false + generate_performance_plots: false + ############################# detection: diff --git a/docs/contributing.md b/docs/contributing.md index bfe1d528c9..320e775ca1 100644 --- a/docs/contributing.md +++ b/docs/contributing.md @@ -167,6 +167,14 @@ Once all modules are done processing, EvidenceHandler is killed by the Process m - It runs the unit tests first, then the integration tests. - Please get familiar with pytest first https://docs.pytest.org/en/stable/how-to/output.html +### What does `generate_performance_plots` do? + +- `Debug.generate_performance_plots` in [config/slips.yaml](config/slips.yaml) is a developer-only debugging switch for performance investigations. +- When it is `true`, Slips writes extra CSVs under `output/performance_plots/csv/`, including alert latency (`latency.csv`), profiler worker latency (`profiler_worker_*_latency.csv`), and throughput (`flows_per_minute.csv`). +- On shutdown, the process manager turns those CSVs into plots and metrics under `output/performance_plots/` and `output/metrics.txt`. +- Leave it `false` for normal development and production-style runs. Enabling it adds Redis bookkeeping, file writes, and plot-generation work that are only useful when diagnosing throughput or latency behavior. +- The plots shown in [docs/immune/stress_testing.md](docs/immune/stress_testing.md) were generated with this parameter enabled. + ### Where and how do we get the GW info? Using one of these 3 ways diff --git a/docs/images/immune/c3/stress_testing/after_optimizations.jpg b/docs/images/immune/c3/stress_testing/after_optimizations.jpg new file mode 100644 index 0000000000..51616858f0 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/after_optimizations.jpg differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_flows_per_minute_for_all_profilers b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_flows_per_minute_for_all_profilers new file mode 100644 index 0000000000..37766d65bc Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_flows_per_minute_for_all_profilers differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_latency_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_latency_plot new file mode 100644 index 0000000000..456673a5a1 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_latency_plot differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_throughput_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_throughput_plot new file mode 100644 index 0000000000..48926f0fbc Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-1_throughput_plot differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_flows_per_minute_for_all_profilers b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_flows_per_minute_for_all_profilers new file mode 100644 index 0000000000..b26b7c0c87 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_flows_per_minute_for_all_profilers differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_latency_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_latency_plot new file mode 100644 index 0000000000..48450a679c Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_latency_plot differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_throughput_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_throughput_plot new file mode 100644 index 0000000000..c9c90fa209 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Mixed-Capture-2_throughput_plot differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_flows_per_minute_for_all_profilers b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_flows_per_minute_for_all_profilers new file mode 100644 index 0000000000..23a84f4f4a Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_flows_per_minute_for_all_profilers differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_latency_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_latency_plot new file mode 100644 index 0000000000..6acd7aa727 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_latency_plot differ diff --git a/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_throughput_plot b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_throughput_plot new file mode 100644 index 0000000000..d49795d56f Binary files /dev/null and b/docs/images/immune/c3/stress_testing/baseline/CTU-Normal-18_throughput_plot differ diff --git a/docs/images/immune/c3/stress_testing/soak_testing/flows_graph_from_conn_log.png b/docs/images/immune/c3/stress_testing/soak_testing/flows_graph_from_conn_log.png new file mode 100644 index 0000000000..5afd4a34b4 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/soak_testing/flows_graph_from_conn_log.png differ diff --git a/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_flows_per_minute_for_all_profilers b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_flows_per_minute_for_all_profilers new file mode 100644 index 0000000000..affc7d5c7f Binary files /dev/null and b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_flows_per_minute_for_all_profilers differ diff --git a/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_latency_plot b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_latency_plot new file mode 100644 index 0000000000..7662b2ac97 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_latency_plot differ diff --git a/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_throughput_plot b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_throughput_plot new file mode 100644 index 0000000000..de1c1bd78b Binary files /dev/null and b/docs/images/immune/c3/stress_testing/soak_testing/soak_testing_3_throughput_plot differ diff --git a/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_graph_from_conn_log.png b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_graph_from_conn_log.png new file mode 100644 index 0000000000..775974c386 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_graph_from_conn_log.png differ diff --git a/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_per_minute_for_all_profilers.png b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_per_minute_for_all_profilers.png new file mode 100644 index 0000000000..897b9ebd8f Binary files /dev/null and b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_flows_per_minute_for_all_profilers.png differ diff --git a/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_latency_plot.png b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_latency_plot.png new file mode 100644 index 0000000000..00374b2f35 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_latency_plot.png differ diff --git a/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_throughput_plot.png b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_throughput_plot.png new file mode 100644 index 0000000000..db265d6360 Binary files /dev/null and b/docs/images/immune/c3/stress_testing/sudden_spikes/sudden_spikes_throughput_plot.png differ diff --git a/docs/immune/Immune.md b/docs/immune/Immune.md index 384e953197..621b5f6f4b 100644 --- a/docs/immune/Immune.md +++ b/docs/immune/Immune.md @@ -15,6 +15,7 @@ This is the main guide to the documentation related to the changes done to Slips - [Testing](https://stratospherelinuxips.readthedocs.io/en/develop/immune/testing.html) - [LLM Research and Selection](https://stratospherelinuxips.readthedocs.io/en/develop/immune/research_and_selection_of_llm_candidates.html) - [LLM RPI Performance](https://stratospherelinuxips.readthedocs.io/en/develop/immune/research_rpi_llm_performance.html) +- [Stress Testing](https://stratospherelinuxips.readthedocs.io/en/develop/immune/stress_testing.html) ### Security & Network Configuration diff --git a/docs/immune/stress_testing.md b/docs/immune/stress_testing.md new file mode 100644 index 0000000000..76eba1e546 --- /dev/null +++ b/docs/immune/stress_testing.md @@ -0,0 +1,287 @@ +# Stress Testing Slips + +- [Stress Testing Slips](#stress-testing-slips) + * [Goal](#goal) + * [Context](#context) + * [Baseline](#baseline) + + [Baseline experiments overview](#baseline-experiments-overview) + + [Baseline Experiment 1 - CTU-Mixed-Capture-1](#baseline-experiment-1---ctu-mixed-capture-1) + + [Baseline Experiment 2 - CTU-Mixed-Capture-2](#baseline-experiment-2---ctu-mixed-capture-2) + + [Baseline Experiment 3 - CTU-Normal-18](#baseline-experiment-3---ctu-normal-18) + + [Baseline conclusions](#baseline-conclusions) + * [Stress testing](#stress-testing) + + [Sudden traffic spikes](#sudden-traffic-spikes) + - [Sudden-spikes experiment overview](#sudden-spikes-experiment-overview) + - [Percentile metrics](#percentile-metrics) + - [Sudden-spikes plots and commentary](#sudden-spikes-plots-and-commentary) + - [Flows/min for all profilers combined](#flows-min-for-all-profilers-combined) + - [Flows/min for each profiler](#flows-min-for-each-profiler) + - [Latency over time](#latency-over-time) + - [Sudden-spikes conclusions](#sudden-spikes-conclusions) + + [Soak testing - sustained high traffic (scenario 2)](#soak-testing---sustained-high-traffic--scenario-2-) + - [Soak testing experiment overview](#soak-testing-experiment-overview) + - [Percentile metrics](#percentile-metrics-1) + - [Soak-testing plots and commentary](#soak-testing-plots-and-commentary) + - [Flows/min for all profilers combined](#flows-min-for-all-profilers-combined-1) + - [Flows/min for each profiler](#flows-min-for-each-profiler-1) + - [Latency over time](#latency-over-time-1) + - [Soak-testing conclusions](#soak-testing-conclusions) + * [Fixes](#fixes) + +## Goal + +The goal of the following expirements is to figure out the pressure at which Slips breaks. + +Slips breaks may take one of the following forms: + +**Soft Break** +The state of Slips at which Slips shows significantly reduced unacceptable performance. (for example, when input reading speed diverges from profiler throughput, or latency increases sharply). + +**Hard Break** +Complete system crash or failure of the Slips processes. + + +But before trying to break Slips, we first need to identify what is normal (the baseline). This answers the question, “How does Slips behave under normal conditions?” Then, during stress testing, when we observe something that deviates from the baseline, we can identify it easily. + +## Context + +In the following experiments we will be focusing mainly on the performance of the Input and Profilers of Slips as they are the two main performance bottlenecks, and we will be comparing them to the amount of flows slips receives to determin latency and speed issues. + +The latency we're interested in here means "how long did Slips take to detect a given attack after the attack was completed". + +Please check [how Slips works](https://stratospherelinuxips.readthedocs.io/en/develop/immune/performance_evaluation.html#how-slips-works) for context on what profilers/input process are. + +All throughput and latency plots in this document were generated with +`Debug.generate_performance_plots: true` in config/slips.yaml. +That flag makes Slips record extra performance CSVs during the run and render +the plots during shutdown. + +## Baseline + +### Baseline experiments overview + +We conducted 3 experiments on mixed traffic (normal and malicious) to measure slips performance. These PCAPs were chosen because they mimic normal user traffic. mostly benign with a few malicious/suspicious things going on every now and then. + + +
+ +| Experiment name | Input avg (flows/min) | Input peak (flows/min) | Profiler avg (flows/min) | Avg gap (input vs profiler) | Latency avg (seconds) | Latency p95 | Latency p99 | Max latency | Summary (plots + metrics) | +|---|---:|---:|---:|---:|---:|---:|---:|---:|---| +| CTU-Mixed-Capture-1 | 10,836.20 | 23,404 | 10,426.60 | 3.78% | 0.04 | 0 | 0 | 32 | Five throughput samples only; small average gap and only two non-zero latency samples. | +| CTU-Mixed-Capture-2 | 7,607.50 | 15,215 | 7,425.00 | 2.40% | 1.93 | 20 | 29 | 32 | Two throughput samples only; profiler drains backlog after input falls to zero and latency tail is short. | +| CTU-Normal-18 | 11,688.33 | 21,277 | 8,925.00 | 23.64% | 1.44 | 8.40 | 30 | 52 | Largest baseline throughput gap, but latency is still mostly zero aside from a few isolated spikes. | + +
+ + +### Baseline Experiment 1 - CTU-Mixed-Capture-1 + +**Traffic** + +https://mcfp.felk.cvut.cz/publicDatasets/CTU-Mixed-Capture-1/ + + +**Flows/min for all profilers combined** + + + +Input peaks at 23,404 flows/min, while combined profiler throughput peaks at 11,967 flows/min and continues draining after input drops to zero. + +**Flows/min for each profiler** + + + +The five profilers are closely balanced; their per-minute peaks range from 2,316 to 2,514 flows/min. + +**Latency over time** + + + +Latency is effectively flat: 1,214 of 1,216 samples are 0s, with only two spikes at 18s and 32s. + +### Baseline Experiment 2 - CTU-Mixed-Capture-2 + +**Traffic** + +https://mcfp.felk.cvut.cz/publicDatasets/CTU-Mixed-Capture-2/ + +**Flows/min for all profilers combined** + + + +There are only two throughput samples: 15,215 input flows/min followed by a drain minute where profiler throughput reaches 9,636 flows/min after input is already zero. + +**Flows/min for each profiler** + + + +The workers remain fairly even during the drain minute, peaking between 1,876 and 2,080 flows/min. + +**Latency over time** + + + +Latency is mostly 0s, with a short early tail up to 32s; p95 is 20s and p99 is 29s. + +### Baseline Experiment 3 - CTU-Normal-18 + +**Traffic** + +https://mcfp.felk.cvut.cz/publicDatasets/CTU-Normal-18/ + +**Flows/min for all profilers combined** + + + +The first minute reaches 21,277 input flows/min versus 6,402 profiled, and the profilers keep draining until they peak at 10,355 flows/min after input stops. + +**Flows/min for each profiler** + + + +Profiler load is still balanced overall, with worker 2 slightly ahead and peaking at 2,239 flows/min. + +**Latency over time** + + + +Most latency samples are 0s; the tail comes from a handful of spikes, including a single 52s maximum. + +--- + +### Baseline conclusions +| Check | Result | Reason | +|---|---|---| +| Soft Break FPS | Not reached in baseline | CTU-Mixed-Capture-1 and CTU-Mixed-Capture-2 stay at 3.78% and 2.40% average throughput gap. CTU-Normal-18 reaches a 23.64% gap, but its latency still stays mostly at 0s with p95 at 8.40s. | +| Hard Break | Not observed | All experiments produced metrics and plots; no indication of process failure in outputs. | + +--- + +## Stress testing + +Now we try to get Slips to break. + +### Sudden traffic spikes + + +This scenario covers sudden-spikes experiment. The input traffic pattern is designed to simulate sudden bursts of network activity, with spikes reaching up to 10,281 flows/min every 10 minutes. The goal is to evaluate how Slips handles these abrupt increases in load and whether it can maintain performance without significant degradation or failure. + +#### Sudden-spikes experiment overview +
+ +| Experiment name | Input avg (flows/min) | Input peak (flows/min) | Profiler avg (flows/min) | Profiler peak (flows/min) | Avg gap (input vs profiler) | Latency avg (seconds) | Latency p95 | Latency p99 | Summary (plots + metrics) | +|---|---:|---:|---:|---:|---:|---:|---:|---:|---| +| sudden_spikes | 439.08 | 10,281 | 439.07 | 10,281 | 0.0006% | 1,134.63 | 11,610 | 17,715 | Combined throughput almost perfectly matches input, but latency degrades severely late in the run. | + +
+ +#### Percentile metrics +
+ +| Metric | p50 | p95 | p99 | Avg | +|---|---:|---:|---:|---:| +| Input flows/min | 253.5 | 944.5 | 5,200.44 | 439.08 | +| Profiler flows/min (all) | 254.0 | 1,222.2 | 5,049.02 | 439.07 | +| Latency (seconds) | 166.0 | 11,610.0 | 17,715.0 | 1,134.63 | + +
+ +#### Sudden-spikes plots and commentary + +#### Flows/min for all profilers combined + + + +The combined profiler series matches input exactly in 310 of 378 minutes; the visible mismatches are short catch-up periods immediately after large bursts. + +#### Flows/min for each profiler + + + +Spike load is spread fairly evenly across the profilers, but worker 5 does not contribute until 10 minutes into the run. + +#### Latency over time + + + +Latency starts in the low hundreds of seconds and then explodes late in the run; the last quarter alone pushes p95 to 17,715s and the maximum to 17,718s. + +#### Sudden-spikes conclusions +| Check | Result | Reason | +|---|---|-----------------------------------------------------------------------------------------------------------------| +| Soft Break FPS | Reached (latency-driven) | Throughput keeps up with input, but latency rises to 19 mins on average with p95 at 11,610s and p99 at 17,715s. | +| Hard Break | Not observed | Metrics and plots are complete; no evidence of a process crash. | + + + +--- +### Soak testing - sustained high traffic (scenario 2) + +This scenario covers soak-testing experiment. The input traffic pattern is designed to simulate sustained high traffic activity. The goal is to evaluate how Slips handles these increases in load for a long period of time and whether it can maintain performance without significant degradation or failure. + +#### Soak testing experiment overview +
+ +| Experiment name | Input avg (flows/min) | Input peak (flows/min) | Profiler avg (flows/min) | Profiler peak (flows/min) | Avg gap (input vs profiler) | Latency avg (seconds) | Latency p95 | Latency p99 | Summary (plots + metrics) | +|---|---:|---:|---:|---:|---:|---:|---:|---:|---| +| soak_testing | 8,686.36 | 10,391 | 4,974.73 | 5,892 | 42.73% | 688.37 | 1,134.0 | 1,206.76 | Profiler throughput stays well below input throughout the run, and latency keeps rising instead of stabilizing. | + +
+ +#### Percentile metrics +
+ +| Metric | p50 | p95 | p99 | Avg | +|---|---:|---:|---:|---:| +| Input flows/min | 8,846.0 | 9,991.05 | 10,381.54 | 8,686.36 | +| Profiler flows/min (all) | 5,343.0 | 5,770.70 | 5,878.24 | 4,974.73 | +| Latency (seconds) | 708.0 | 1,134.0 | 1,206.76 | 688.37 | + +
+ +#### Soak-testing plots and commentary + + +#### Flows/min for all profilers combined + + +Input stays high between 2,643 and 10,391 flows/min, while combined profiler throughput never exceeds 5,892 flows/min. + +#### Flows/min for each profiler + + + + +Only workers 0-2 carry traffic at the start; workers 3, 4, and 5 begin contributing roughly 10, 15, and 20 minutes into the run because slips adds more workers the more throughput it detects. here, the throughput gap remains large. + +#### Latency over time + + + +Latency grows through the run instead of flattening. This is considered a soft break. Slips is unable to keep up a tolerable performance under constant heavy load. We consider this the main issue that needs to be solved. + + + +#### Soak-testing conclusions +| Check | Result | Reason | +|---|-------------|----------------------------------------| +| Soft Break FPS | Reached | Profiler throughput averages 4,974.73 flows/min against 8,686.36 input flows/min, and latency grows from a 708s median to a 2,166s maximum. | +| Hard Break | Not observed | The CSV series continue through the end of the run, so the data shows severe degradation but not a crash. | + + +## Fixes +After many experiments, trials and failures, and optimizations, we managed to get acceptable latency in Slips under high traffic + + + + +**PRs solving the above issues, and resource-related issues discovered while testing can be found here:** + +* DoS Protector: https://github.com/stratosphereips/StratosphereLinuxIPS/issues/1767 +* Latency issue https://github.com/stratosphereips/StratosphereLinuxIPS/issues/1838 and https://github.com/stratosphereips/StratosphereLinuxIPS/pull/1858 +* Incomplete processing of flows: https://github.com/stratosphereips/StratosphereLinuxIPS/issues/1848 + +Resource related issues: + +http://github.com/stratosphereips/StratosphereLinuxIPS/issues/1827 +https://github.com/stratosphereips/StratosphereLinuxIPS/issues/1815 diff --git a/managers/process_manager.py b/managers/process_manager.py index 876809b9da..13e295f943 100644 --- a/managers/process_manager.py +++ b/managers/process_manager.py @@ -37,6 +37,7 @@ from slips_files.common.abstracts.imodule import ( IModule, ) +from slips_files.common.plotter import Plotter from slips_files.common.style import green from slips_files.common.input_type import InputType @@ -786,6 +787,13 @@ def shutdown_gracefully(self): """ try: print = self.get_print_function() + if self.main.conf.generate_performance_plots() is True: + self.plotter = Plotter(self.main.args.output, print) + self.plotter.plot_latency_csv() + self.plotter.plot_profiler_latency_csvs() + self.plotter.plot_throughput_csv() + self.plotter.write_throughput_metrics() + self.plotter.plot_flows_from_conn_log() if not self.main.args.stopdaemon: print("\n" + "-" * 27) diff --git a/modules/network_discovery/network_discovery.py b/modules/network_discovery/network_discovery.py index 841dc8d187..7931b44a51 100644 --- a/modules/network_discovery/network_discovery.py +++ b/modules/network_discovery/network_discovery.py @@ -43,12 +43,12 @@ def init(self): self.classifier = FlowClassifier() def subscribe_to_channels(self): - self.c1 = self.db.subscribe("tw_modified") + self.c1 = self.db.subscribe("new_flow") self.c2 = self.db.subscribe("new_notice") self.c3 = self.db.subscribe("new_dhcp") self.c4 = self.db.subscribe("tw_closed") self.channels = { - "tw_modified": self.c1, + "new_flow": self.c1, "new_notice": self.c2, "new_dhcp": self.c3, "tw_closed": self.c4, @@ -191,7 +191,7 @@ def pre_main(self): utils.drop_root_privs_permanently() def main(self): - if msg := self.get_msg("tw_modified"): + if msg := self.get_msg("new_flow"): msg = json.loads(msg["data"]) profileid = msg["profileid"] twid = msg["twid"] diff --git a/slips/main.py b/slips/main.py index 6aa219b9e4..4bd2376958 100644 --- a/slips/main.py +++ b/slips/main.py @@ -22,6 +22,7 @@ from managers.redis_manager import RedisManager from managers.ui_manager import UIManager from slips_files.common.parsers.config_parser import ConfigParser +from slips_files.common.performance_paths import get_performance_plots_dir from slips_files.common.printer import Printer from slips_files.common.slips_utils import utils from slips_files.common.style import green, yellow @@ -428,8 +429,11 @@ def get_analyzed_flows_percentage(self) -> str: processed = self.db.get_flow_analyzed_by_the_profiler_so_far() if not processed: return "" + try: + percentage = (processed / self.total_flows) * 100 + except ZeroDivisionError: + return "" - percentage = (processed / self.total_flows) * 100 # in very large pcaps, thousands of flows are nothing compared to # the tot flows, so if the percentage is int, slips would print 0% # for a while, so we take the first number after the floating point @@ -694,6 +698,12 @@ def sig_handler(sig, frame): "of traffic by querying TI sites." ) + if self.conf.generate_performance_plots(): + self.print( + f"Slips will generate performance plots on shutdown in " + f"{green(get_performance_plots_dir(self.args.output))}." + ) + while (not self.proc_man.should_stop_slips()) and ( not self.sigterm_received ): diff --git a/slips_files/common/parsers/config_parser.py b/slips_files/common/parsers/config_parser.py index 2bd7fb5e5d..c23d058815 100644 --- a/slips_files/common/parsers/config_parser.py +++ b/slips_files/common/parsers/config_parser.py @@ -302,6 +302,11 @@ def debug(self): debug = 0 return debug + def generate_performance_plots(self) -> bool: + return self.read_configuration( + "Debug", "generate_performance_plots", False + ) + def export_to(self): return self.read_configuration("exporting_alerts", "export_to", []) diff --git a/slips_files/common/performance_paths.py b/slips_files/common/performance_paths.py new file mode 100644 index 0000000000..0da8c66bd9 --- /dev/null +++ b/slips_files/common/performance_paths.py @@ -0,0 +1,27 @@ +# SPDX-FileCopyrightText: 2021 Sebastian Garcia +# SPDX-License-Identifier: GPL-2.0-only +import os + + +PERFORMANCE_PLOTS_DIRNAME = "performance_plots" +PERFORMANCE_CSV_DIRNAME = "csv" + + +def get_performance_plots_dir(output_dir: str) -> str: + return os.path.join(output_dir or "", PERFORMANCE_PLOTS_DIRNAME) + + +def get_performance_csv_dir(output_dir: str) -> str: + """ + csv files used for generating the plots go into + output/performance_plots/csv/ + This func returns that path + """ + return os.path.join( + get_performance_plots_dir(output_dir), PERFORMANCE_CSV_DIRNAME + ) + + +def get_performance_csv_path(output_dir: str, filename: str) -> str: + """returns the full path to the given filename inside the csv dir""" + return os.path.join(get_performance_csv_dir(output_dir), filename) diff --git a/slips_files/common/plotter.py b/slips_files/common/plotter.py new file mode 100644 index 0000000000..74910e0ebe --- /dev/null +++ b/slips_files/common/plotter.py @@ -0,0 +1,469 @@ +# SPDX-FileCopyrightText: 2021 Sebastian Garcia +# SPDX-License-Identifier: GPL-2.0-only +import csv +import glob +import math +import os +import statistics +import subprocess +import sys + +from slips_files.common.performance_paths import ( + get_performance_csv_dir, + get_performance_csv_path, + get_performance_plots_dir, +) + + +class Plotter: + def __init__(self, output_dir, print_func): + self.output_dir = output_dir or "" + self.print = print_func + self.plots_dir = get_performance_plots_dir(self.output_dir) + self.csv_dir = get_performance_csv_dir(self.output_dir) + + def plot_latency_csv(self): + latency_path = get_performance_csv_path(self.output_dir, "latency.csv") + if not self._is_valid_input(latency_path): + return + + ts_values = [] + latency_values = [] + try: + with open(latency_path, newline="") as csv_file: + reader = csv.DictReader(csv_file) + for row in reader: + ts = row.get("ts") + latency = row.get("latency") + if ts is None or latency is None: + continue + try: + ts_values.append(float(ts)) + latency_values.append(float(latency)) + except ValueError: + continue + except Exception as exc: + self._log(f"[Plotter] Failed to read latency.csv: {exc}") + return + + if not ts_values: + return + + output_path = os.path.join( + self.plots_dir, "latency_of_each_evidence_from_alerts_json.png" + ) + self._save_plot( + output_path, + ts_values, + {"latency": latency_values}, + xlabel="ts", + ylabel="latency", + title="Latency", + ) + + def plot_profiler_latency_csvs(self): + if not self.output_dir: + return + + csv_paths = sorted( + glob.glob( + os.path.join(self.csv_dir, "profiler_worker_*_latency.csv") + ) + ) + if not csv_paths: + return + + os.makedirs(self.plots_dir, exist_ok=True) + output_path = os.path.join( + self.plots_dir, "all_profiler_workers_latency.png" + ) + + try: + import matplotlib + + matplotlib.use("Agg") + from matplotlib import pyplot as plt + except Exception as exc: + self._log(f"[Plotter] Skipping plot {output_path}: {exc}") + return + + try: + plt.figure(figsize=(10, 4)) + plotted_any_series = False + + for csv_path in csv_paths: + ts_values = [] + latency_values = [] + with open(csv_path, newline="", encoding="utf-8") as csv_file: + reader = csv.DictReader(csv_file) + for row in reader: + try: + ts_values.append(float(row["timestamp_now"])) + latency_values.append( + float(row["latency_in_seconds"]) + ) + except (KeyError, TypeError, ValueError): + continue + + if not ts_values: + continue + + label = os.path.basename(csv_path).replace("_latency.csv", "") + plt.plot(ts_values, latency_values, linewidth=1.0, label=label) + plotted_any_series = True + + if not plotted_any_series: + plt.close() + return + + plt.xlabel("timestamp_now") + plt.ylabel("latency_in_seconds") + plt.title("Profiler latency") + plt.legend(fontsize="small", ncol=2) + plt.tight_layout() + plt.savefig(output_path, format="png") + plt.close() + self._log(f"[Plotter] Saved plot to {output_path}") + except Exception as exc: + self._log(f"[Plotter] Failed to save plot {output_path}: {exc}") + + def write_latency_metrics(self, metrics_path=None): + latency_path = get_performance_csv_path(self.output_dir, "latency.csv") + if not self.output_dir or not os.path.exists(latency_path): + return + + latency_values = [] + try: + with open(latency_path, newline="") as csv_file: + reader = csv.DictReader(csv_file) + if not reader.fieldnames or "latency" not in reader.fieldnames: + return + for row in reader: + raw_latency = row.get("latency") + try: + latency_values.append(float(raw_latency)) + except (TypeError, ValueError): + pass + except Exception as exc: + self._log(f"[Plotter] Failed to read latency.csv: {exc}") + return + + latency_p50 = self._percentile(latency_values, 50) + latency_p95 = self._percentile(latency_values, 95) + latency_p99 = self._percentile(latency_values, 99) + latency_avg = self._average(latency_values) + + if metrics_path is None: + metrics_path = os.path.join(self.output_dir, "metrics.txt") + lines = [ + "latency.cs:v metrics:", + f"p50 for latency: {self._format_metric(latency_p50)}", + f"p95 for latency: {self._format_metric(latency_p95)}", + f"p99 for latency: {self._format_metric(latency_p99)}", + f"avg for latency: {self._format_metric(latency_avg)}", + "\n\n", + ] + try: + with open(metrics_path, "a", encoding="utf-8") as handle: + handle.write("\n".join(lines) + "\n") + except Exception as exc: + self._log(f"[Plotter] Failed to write metrics.txt: {exc}") + + def plot_throughput_csv(self): + throughput_path = get_performance_csv_path( + self.output_dir, "flows_per_minute.csv" + ) + if not self._is_valid_input(throughput_path): + return + + ts_values = [] + series = {} + profiler_columns = [] + try: + with open(throughput_path, newline="") as csv_file: + reader = csv.DictReader(csv_file) + if not reader.fieldnames or "ts" not in reader.fieldnames: + return + + # recognize profiler columns + for column in reader.fieldnames: + if column == "ts": + continue + series[column] = [] + if column.startswith("profiler_flows_per_min_worker"): + profiler_columns.append(column) + + for row in reader: + ts = row.get("ts") + if ts is None: + continue + try: + ts_values.append(float(ts)) + except ValueError: + continue + + for column in series: + raw_value = row.get(column) + try: + series[column].append(float(raw_value)) + except (TypeError, ValueError): + series[column].append(float("nan")) + except Exception as exc: + self._log(f"[Plotter] Failed to read flows_per_minute.csv: {exc}") + return + + if not ts_values: + return + + labeled_series = {} + for column, values in series.items(): + label = column + if column == "input_flows_per_min": + label = "input" + elif column.startswith("profiler_flows_per_min_worker"): + suffix = column.replace("profiler_flows_per_min_worker", "") + label = f"profiler{suffix}" + labeled_series[label] = values + + throughput_output_path = os.path.join( + self.plots_dir, "input_proc_flows_per_min.png" + ) + self._save_plot( + throughput_output_path, + ts_values, + labeled_series, + xlabel="ts", + ylabel="flows_per_min", + title="Flows per minute", + ) + + if profiler_columns: + profiler_sum = [] + for idx in range(len(ts_values)): + total = 0.0 + for column in profiler_columns: + try: + value = series[column][idx] + except IndexError: + value = float("nan") + if value == value: + total += value + profiler_sum.append(total) + + combined_output_path = os.path.join( + self.plots_dir, + "flows_per_minute_seen_by_all_profilers_combined.png", + ) + self._save_plot( + combined_output_path, + ts_values, + {"combined": profiler_sum}, + xlabel="ts", + ylabel="flows_per_min", + title="flows_per_minute_for_all_profilers.csv combined", + ) + + def write_throughput_metrics(self): + throughput_path = get_performance_csv_path( + self.output_dir, "flows_per_minute.csv" + ) + if not self.output_dir or not os.path.exists(throughput_path): + return + + input_values = [] + profiler_sums = [] + profiler_columns = [] + try: + with open(throughput_path, newline="") as csv_file: + reader = csv.DictReader(csv_file) + if not reader.fieldnames or "ts" not in reader.fieldnames: + return + + for column in reader.fieldnames: + if column.startswith("profiler_flows_per_min"): + profiler_columns.append(column) + + for row in reader: + raw_input = row.get("input_flows_per_min") + try: + input_values.append(float(raw_input)) + except (TypeError, ValueError): + pass + + total = 0.0 + for column in profiler_columns: + raw_value = row.get(column) + try: + value = float(raw_value) + except (TypeError, ValueError): + continue + if not math.isnan(value): + total += value + profiler_sums.append(total) + except Exception as exc: + self._log(f"[Plotter] Failed to read flows_per_minute.csv: {exc}") + return + + input_p50 = self._percentile(input_values, 50) + input_p95 = self._percentile(input_values, 95) + input_p99 = self._percentile(input_values, 99) + input_avg = self._average(input_values) + profiler_p50 = self._percentile(profiler_sums, 50) + profiler_p95 = self._percentile(profiler_sums, 95) + profiler_p99 = self._percentile(profiler_sums, 99) + profiler_avg = self._average(profiler_sums) + + metrics_path = os.path.join(self.output_dir, "metrics.txt") + lines = [ + "flows_per_minute.csv metrics:", + f"p50 for input: {self._format_metric(input_p50)}", + f"p95 for input: {self._format_metric(input_p95)}", + f"p99 for input: {self._format_metric(input_p99)}", + f"avg for input: {self._format_metric(input_avg)}", + ("p50 for all profilers: " f"{self._format_metric(profiler_p50)}"), + ("p95 for all profilers: " f"{self._format_metric(profiler_p95)}"), + ("p99 for all profilers: " f"{self._format_metric(profiler_p99)}"), + ("avg for all profilers: " f"{self._format_metric(profiler_avg)}"), + "\n\n", + ] + try: + with open(metrics_path, "w", encoding="utf-8") as handle: + handle.write("\n".join(lines) + "\n") + except Exception as exc: + self._log(f"[Plotter] Failed to write metrics.txt: {exc}") + return + + self.write_latency_metrics(metrics_path=metrics_path) + + def plot_flows_from_conn_log(self): + conn_log = os.path.join(self.output_dir, "zeek_files", "conn.log") + if not os.path.exists(conn_log): + return + + os.makedirs(self.plots_dir, exist_ok=True) + output_plot = os.path.join( + self.plots_dir, "flows_per_second_seen_in_conn_log.png" + ) + # Assuming stress_testing_scripts is in the project root. + # This file is in slips_files/common/plotter.py + # So project root is 2 levels up. + current_dir = os.path.dirname(os.path.abspath(__file__)) + project_root = os.path.abspath(os.path.join(current_dir, "../..")) + script_path = os.path.join( + project_root, "stress_testing_scripts", "plot_flows_over_time.py" + ) + + if not os.path.exists(script_path): + self._log( + f"[Plotter] Could not find plot_flows_over_time.py at " + f"{script_path}" + ) + return + + cmd = [ + sys.executable, + script_path, + "--conn-log", + conn_log, + "--output", + output_plot, + ] + + try: + subprocess.run( + cmd, check=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE + ) + self._log(f"[Plotter] Saved flows over time plot to {output_plot}") + except subprocess.CalledProcessError as e: + self._log( + f"[Plotter] Failed to run plot_flows_over_time.py: {e.stderr}" + ) + except Exception as exc: + self._log( + f"[Plotter] Error running plot_flows_over_time.py: {exc}" + ) + + def _is_valid_input(self, csv_path): + if not self.output_dir: + return False + if not os.path.exists(csv_path): + return False + os.makedirs(self.plots_dir, exist_ok=True) + return True + + def _save_plot( + self, output_path, ts_values, series, xlabel, ylabel, title + ): + try: + import matplotlib + + matplotlib.use("Agg") + from matplotlib import pyplot as plt + except Exception as exc: + self._log(f"[Plotter] Skipping plot {output_path}: {exc}") + return + + try: + plt.figure(figsize=(10, 4)) + for label, values in series.items(): + plt.plot(ts_values, values, linewidth=1.0, label=label) + plt.xlabel(xlabel) + plt.ylabel(ylabel) + plt.title(title) + if len(series) > 1: + plt.legend(fontsize="small", ncol=2) + plt.tight_layout() + plt.savefig(output_path, format="png") + plt.close() + self._log(f"[Plotter] Saved plot to {output_path}") + except Exception as exc: + self._log(f"[Plotter] Failed to save plot {output_path}: {exc}") + + def _log(self, message): + if self.print: + self.print(message, log_to_logfiles_only=True) + + def _percentile(self, values, percentile): + clean = [] + for value in values: + if value is None: + continue + try: + if math.isnan(value): + continue + except TypeError: + continue + clean.append(value) + if not clean: + return float("nan") + clean.sort() + if len(clean) == 1: + return clean[0] + rank = (len(clean) - 1) * (percentile / 100.0) + lower = math.floor(rank) + upper = math.ceil(rank) + if lower == upper: + return clean[int(rank)] + lower_value = clean[lower] + upper_value = clean[upper] + return lower_value + (upper_value - lower_value) * (rank - lower) + + def _average(self, values): + clean = [] + for value in values: + if value is None: + continue + try: + if math.isnan(value): + continue + except TypeError: + continue + clean.append(value) + if not clean: + return float("nan") + return statistics.fmean(clean) + + def _format_metric(self, value): + if math.isnan(value): + return "nan" + return f"{value}" diff --git a/slips_files/common/slips_utils.py b/slips_files/common/slips_utils.py index 377f651df9..000d4bd4bc 100644 --- a/slips_files/common/slips_utils.py +++ b/slips_files/common/slips_utils.py @@ -307,6 +307,7 @@ def are_detection_modules_interested_in_this_ip(self, ip) -> bool: """ Check if any of the scan detection modules (horizontal portscan, vertical portscan, icmp scan) are interested in this ip + these modules are only interested in private or public ipv4 """ try: ip_obj = ipaddress.ip_address(ip) diff --git a/slips_files/core/database/database_manager.py b/slips_files/core/database/database_manager.py index 6fb1f745b6..bbf6602db3 100644 --- a/slips_files/core/database/database_manager.py +++ b/slips_files/core/database/database_manager.py @@ -1,13 +1,17 @@ # SPDX-FileCopyrightText: 2021 Sebastian Garcia # SPDX-License-Identifier: GPL-2.0-only +import csv import json import os import shutil import sqlite3 +import time from pathlib import Path from typing import ( - List, Dict, + Iterable, + List, + Optional, ) @@ -16,6 +20,7 @@ from slips_files.core.database.redis_db.database import RedisDB from slips_files.core.database.sqlite_db.database import SQLiteDB from slips_files.common.parsers.config_parser import ConfigParser +from slips_files.common.performance_paths import get_performance_csv_path from slips_files.core.structures.evidence import Evidence from slips_files.core.structures.alerts import Alert from slips_files.core.output import Output @@ -262,6 +267,9 @@ def set_local_network(self, *args, **kwargs): def get_local_network(self, *args, **kwargs): return self.rdb.get_local_network(*args, **kwargs) + def get_total_recognized_localnets(self, *args, **kwargs): + return self.rdb.get_total_recognized_localnets(*args, **kwargs) + def get_label_count(self, *args, **kwargs): return self.rdb.get_label_count(*args, **kwargs) @@ -298,6 +306,205 @@ def store_module_flows_per_second(self, *args, **kwargs): def get_module_flows_per_second(self, *args, **kwargs): return self.rdb.get_module_flows_per_second(*args, **kwargs) + def record_flow_per_minute(self, module: str, now: Optional[float] = None): + if not self.conf.generate_performance_plots(): + return + + now = time.time() if now is None else now + minute_ts = int(now // 60) * 60 + self.rdb.increment_flows_per_minute(module, minute_ts) + self.rdb.record_flows_per_minute_module(module) + if ( + not hasattr(self, "_last_flows_per_minute_bucket") + or self._last_flows_per_minute_bucket != minute_ts + ): + self._last_flows_per_minute_bucket = minute_ts + self._maybe_log_flows_per_minute(minute_ts) + + def _maybe_log_flows_per_minute(self, minute_ts: int): + if not self.conf.generate_performance_plots(): + return + + if not self.rdb.try_acquire_flows_per_minute_log_lock(): + return + + try: + last_logged = self.rdb.get_last_logged_flows_per_minute() + if last_logged is None: + # Start tracking from the minute before the first flow. + self.rdb.set_last_logged_flows_per_minute(minute_ts - 60) + return + + last_complete_minute = minute_ts - 60 + if last_complete_minute <= last_logged: + return + + modules = self.rdb.get_flows_per_minute_modules() + profiler_modules = sorted( + module + for module in modules + if self._is_profiler_module(module) + ) + for ts in range(last_logged + 60, last_complete_minute + 1, 60): + input_count = self.rdb.get_flows_per_minute("input", ts) + profiler_counts = { + module: self.rdb.get_flows_per_minute(module, ts) + for module in profiler_modules + } + self._append_flows_per_minute_row( + ts, input_count, profiler_counts + ) + self.rdb.set_last_logged_flows_per_minute(ts) + finally: + self.rdb.release_flows_per_minute_log_lock() + + def _append_flows_per_minute_row( + self, ts: int, input_count: int, profiler_counts: Dict[str, int] + ): + output_dir = self.get_output_dir() or self.output_dir + csv_path = get_performance_csv_path(output_dir, "flows_per_minute.csv") + os.makedirs(os.path.dirname(csv_path), exist_ok=True) + profiler_columns = self._get_profiler_columns(profiler_counts.keys()) + desired_header = ["ts", "input_flows_per_min"] + profiler_columns + header = self._ensure_flows_per_minute_header(csv_path, desired_header) + + with open(csv_path, "a", newline="") as handle: + writer = csv.writer(handle) + if os.path.getsize(csv_path) == 0: + writer.writerow(header) + row = self._build_flows_per_minute_row( + ts, input_count, profiler_counts, header + ) + writer.writerow(row) + + def _is_profiler_module(self, module: str) -> bool: + module_lower = module.lower() + return module_lower.startswith("profiler") + + def _get_profiler_columns(self, modules: Iterable[str]) -> List[str]: + columns = [] + for module in modules: + column = self._profiler_column_for_module(module) + if column: + columns.append(column) + return self._sort_profiler_columns(columns) + + def _profiler_column_for_module(self, module: str) -> Optional[str]: + module_lower = module.lower() + if module_lower == "profiler": + return "profiler_flows_per_min" + prefix_map = ( + "profilerworker_process_", + "profilerworker_", + "profiler_worker_", + "profiler_", + ) + for prefix in prefix_map: + if module_lower.startswith(prefix): + suffix = module_lower.split(prefix, 1)[1] + if not suffix: + return "profiler_flows_per_min" + return f"profiler_flows_per_min_worker{suffix}" + return None + + def _sort_profiler_columns(self, columns: List[str]) -> List[str]: + unique_columns = list(dict.fromkeys(columns)) + worker_prefix = "profiler_flows_per_min_worker" + + def sort_key(name: str): + if name == "profiler_flows_per_min": + return (0, -1, "") + if name.startswith(worker_prefix): + suffix = name[len(worker_prefix) :] + if suffix.isdigit(): + return (0, int(suffix), "") + return (1, 0, suffix) + return (2, 0, name) + + return sorted(unique_columns, key=sort_key) + + def _ensure_flows_per_minute_header( + self, csv_path: str, desired_header: List[str] + ) -> List[str]: + if not os.path.exists(csv_path) or os.path.getsize(csv_path) == 0: + return desired_header + + with open(csv_path, newline="") as handle: + reader = csv.reader(handle) + existing_header = next(reader, []) + + if not existing_header: + return desired_header + + if existing_header == desired_header: + return existing_header + + merged_header = self._merge_flows_per_minute_headers( + existing_header, desired_header + ) + if merged_header != existing_header: + self._rewrite_flows_per_minute_csv( + csv_path, existing_header, merged_header + ) + return merged_header + + def _merge_flows_per_minute_headers( + self, existing_header: List[str], desired_header: List[str] + ) -> List[str]: + base_columns = ["ts", "input_flows_per_min"] + profiler_columns = self._sort_profiler_columns( + [ + column + for column in existing_header + desired_header + if column.startswith("profiler_flows_per_min") + ] + ) + other_columns = [ + column + for column in existing_header + desired_header + if column not in base_columns and column not in profiler_columns + ] + other_columns = list(dict.fromkeys(other_columns)) + return base_columns + profiler_columns + other_columns + + def _rewrite_flows_per_minute_csv( + self, csv_path: str, old_header: List[str], new_header: List[str] + ): + tmp_path = f"{csv_path}.tmp" + with open(csv_path, newline="") as handle, open( + tmp_path, "w", newline="" + ) as out_handle: + reader = csv.reader(handle) + writer = csv.writer(out_handle) + next(reader, None) + writer.writerow(new_header) + for row in reader: + row_map = { + old_header[idx]: row[idx] + for idx in range(min(len(old_header), len(row))) + } + writer.writerow( + [row_map.get(column, "0") for column in new_header] + ) + os.replace(tmp_path, csv_path) + + def _build_flows_per_minute_row( + self, + ts: int, + input_count: int, + profiler_counts: Dict[str, int], + header: List[str], + ) -> List[int]: + row_map: Dict[str, int] = { + "ts": ts, + "input_flows_per_min": input_count, + } + for module, count in profiler_counts.items(): + column = self._profiler_column_for_module(module) + if column: + row_map[column] = count + return [row_map.get(column, 0) for column in header] + def get_accumulated_threat_level(self, *args, **kwargs): return self.rdb.get_accumulated_threat_level(*args, **kwargs) diff --git a/slips_files/core/database/redis_db/alert_handler.py b/slips_files/core/database/redis_db/alert_handler.py index dcd00eccb3..d399867493 100644 --- a/slips_files/core/database/redis_db/alert_handler.py +++ b/slips_files/core/database/redis_db/alert_handler.py @@ -277,20 +277,19 @@ def set_evidence(self, evidence: Evidence): evidence_exists: Optional[dict] = self.r.hget( evidence_hash, evidence.id ) + if evidence_exists: + return False + if self.is_whitelisted_evidence(evidence.id): + return False + self.r.hset(evidence_hash, evidence.id, evidence_to_send) + self.r.incr(self.constants.NUMBER_OF_EVIDENCE) # note that publishing HAS TO be done after adding the evidence # to the db # whitelisted evidence are deleted from the db, so we need to check # that we're not re-adding a deleted evidence - if (not evidence_exists) and ( - not self.is_whitelisted_evidence(evidence.id) - ): - self.r.hset(evidence_hash, evidence.id, evidence_to_send) - self.r.incr(self.constants.NUMBER_OF_EVIDENCE) - self.publish(self.channels.EVIDENCE_ADDED, evidence_to_send) - return True - - return False + self.publish(self.channels.EVIDENCE_ADDED, evidence_to_send) + return True def set_alert(self, alert: Alert): self.set_evidence_causing_alert(alert) diff --git a/slips_files/core/database/redis_db/constants.py b/slips_files/core/database/redis_db/constants.py index 2ca9cd6fd4..79af2894ef 100644 --- a/slips_files/core/database/redis_db/constants.py +++ b/slips_files/core/database/redis_db/constants.py @@ -33,7 +33,8 @@ class Constants: CACHED_ASN = "cached_asn" PIDS = "PIDs" MAC = "MAC" - MODIFIED_TIMEWINDOWS = "ModifiedTW" + MODIFIED_TIMEWINDOWS = "modified_timewindows" + TW_FLOWS_COUNTER = "timewindow_flows_counter" ACCUMULATED_THREAT_LEVELS = "accumulated_threat_levels" TRANCO_WHITELISTED_DOMAINS = "tranco_whitelisted_domains" WHITELIST = "whitelist" @@ -108,6 +109,10 @@ class Constants: P2P_PEER_INFO_HASH = "peer_info" FIDES_CACHE_KEY = "fides_cache" FIDES_CACHE_CREATED_SECONDS = "created_seconds" + FLOWS_PER_MINUTE = "flows_per_minute" + FLOWS_PER_MINUTE_MODULES = "flows_per_minute_modules" + FLOWS_PER_MINUTE_LAST_LOGGED = "flows_per_minute_last_logged" + FLOWS_PER_MINUTE_LOG_LOCK = "flows_per_minute_log_lock" class Channels: diff --git a/slips_files/core/database/redis_db/database.py b/slips_files/core/database/redis_db/database.py index f9692ea3a8..fc00011183 100644 --- a/slips_files/core/database/redis_db/database.py +++ b/slips_files/core/database/redis_db/database.py @@ -62,7 +62,6 @@ class RedisDB( # Stores instances per port instances = {} supported_channels = { - "tw_modified", "evidence_added", "new_ip", "new_flow", @@ -370,7 +369,7 @@ def _connect(port: int, db: int) -> redis.StrictRedis: # normally; if it fails, an exception will be thrown return redis.StrictRedis( - host="localhost", + host=LOCALHOST, port=port, db=db, charset="utf-8", @@ -657,6 +656,13 @@ def set_local_network(self, cidr, interface): def get_local_network(self, interface): return self.r.hget(self.constants.LOCAL_NETWORK, interface) + def get_total_recognized_localnets(self): + """ + when slips is running using 2 interfaces, Slips recognizes 2 diff + localnets, so this function is expected to return 2 + """ + return self.r.hlen(self.constants.LOCAL_NETWORK) + def get_used_port(self) -> int: return int(self.r.config_get(self.constants.REDIS_USED_PORT)["port"]) @@ -1481,6 +1487,39 @@ def store_module_flows_per_second(self, module, fps): def get_module_flows_per_second(self, module): return self.r.hget(self.constants.MODULES_FLOWS_PER_SECOND, module) + def increment_flows_per_minute(self, module: str, minute_ts: int) -> int: + key = f"{self.constants.FLOWS_PER_MINUTE}:{module}" + return self.r.hincrby(key, minute_ts, 1) + + def get_flows_per_minute(self, module: str, minute_ts: int) -> int: + key = f"{self.constants.FLOWS_PER_MINUTE}:{module}" + value = self.r.hget(key, minute_ts) + return int(value) if value else 0 + + def record_flows_per_minute_module(self, module: str): + self.r.sadd(self.constants.FLOWS_PER_MINUTE_MODULES, module) + + def get_flows_per_minute_modules(self) -> List[str]: + return list(self.r.smembers(self.constants.FLOWS_PER_MINUTE_MODULES)) + + def get_last_logged_flows_per_minute(self) -> Optional[int]: + value = self.r.get(self.constants.FLOWS_PER_MINUTE_LAST_LOGGED) + return int(value) if value is not None else None + + def set_last_logged_flows_per_minute(self, minute_ts: int): + self.r.set(self.constants.FLOWS_PER_MINUTE_LAST_LOGGED, minute_ts) + + def try_acquire_flows_per_minute_log_lock(self, ttl_seconds: int = 10): + return self.r.set( + self.constants.FLOWS_PER_MINUTE_LOG_LOCK, + "1", + nx=True, + ex=ttl_seconds, + ) + + def release_flows_per_minute_log_lock(self): + self.r.delete(self.constants.FLOWS_PER_MINUTE_LOG_LOCK) + def get_name_of_module_at(self, given_pid): """returns the name of the module that has the given pid""" for name, pid in self.get_pids().items(): diff --git a/slips_files/core/database/redis_db/profile_handler.py b/slips_files/core/database/redis_db/profile_handler.py index 8a0004fc12..40163526c6 100644 --- a/slips_files/core/database/redis_db/profile_handler.py +++ b/slips_files/core/database/redis_db/profile_handler.py @@ -17,7 +17,6 @@ ) import redis import validators -from redis.client import Pipeline from slips_files.core.structures.flow_attributes import Role @@ -1135,7 +1134,6 @@ def check_tw_to_close(self, close_all=False): # Mark the TWs as closed so modules can work on its data pipe = self.r.pipeline() for profile_tw_to_close in profiles_tws_to_close: - pipe.zrem(self.constants.MODIFIED_TIMEWINDOWS, profile_tw_to_close) pipe = self.publish( "tw_closed", profile_tw_to_close, pipeline=pipe @@ -1157,46 +1155,35 @@ def get_current_timewindow(self) -> Optional[str]: def set_current_timewindow(self, timewindow: str) -> Optional[str]: self.r.set(self.constants.CURRENT_TIMEWINDOW, timewindow) - def mark_profile_tw_as_modified( - self, profileid, twid, timestamp, pipe: Pipeline = None - ): + def mark_profile_tw_as_modified(self, modified_tw_details: dict): """ - Mark a TW in a profile as modified - This means: - 1- To add it to the list of ModifiedTW - 2- Add the timestamp received to the time_of_last_modification - in the TW itself - - Modules wait for a TW modification to do some detections. - check the "tw_modified" channel usages to know why this func is - useful - - """ - if not timestamp: - # NEVER use time.time() as a default value for timestamp, - # using it when analyzing Pcaps/files leads to accumulation of tw - # data in RAM > redis getting OOM > slips crashing. - raise ValueError( - "timestamp is required to mark a TW as " - "modified. Received timestamp: None. This " - "leads to Slips running out of memory and crashing." - " Please make sure to provide a timestamp when " - "calling this function." - ) + PS: this function should be as optimized as possible, it's the main + source of latency and it gets called per flow + :param modified_tw_details: a dict with {profileid_tw: ts, ...} to + add to the MODIFIED_TIMEWINDOWS key. + """ + # why are we batch processing? because this function is called in + # an extremely hot path (per flow) and a zadd is O(log N) and we + # need this func to be way faster than that. + # right now, all usages of this key doesn't require it to be 100% + # real-time. so that's why we can batch update it. in the future if + # a usage requires it to be real-time, developers need to come up + # with something that wouldn't introduce latency and keep it + # real-time. - data = {f"{profileid}{self.separator}{twid}": float(timestamp)} - client = pipe if pipe else self.r - client.zadd(self.constants.MODIFIED_TIMEWINDOWS, data) - self.publish( - "tw_modified", - json.dumps( - { - "profileid": profileid, - "twid": twid, - } - ), + pipe = self.r.pipeline() + # without gt, older timestamps can overwrite newer ones + pipe.zadd( + self.constants.MODIFIED_TIMEWINDOWS, + modified_tw_details, + gt=True, ) - return pipe + pipe.zadd( + self.constants.MODIFIED_TIMEWINDOWS, + modified_tw_details, + nx=True, + ) + pipe.execute() def publish_new_letter( self, new_symbol: str, profileid: str, twid: str, tupleid: str, flow diff --git a/slips_files/core/evidence_handler.py b/slips_files/core/evidence_handler.py index ba0408c43c..44003610ab 100644 --- a/slips_files/core/evidence_handler.py +++ b/slips_files/core/evidence_handler.py @@ -20,42 +20,23 @@ # Contact: eldraco@gmail.com, sebastian.garcia@agents.fel.cvut.cz, # stratosphere@aic.fel.cvut.cz -import json -import multiprocessing import threading -from typing import ( - List, - Dict, - Optional, -) -from datetime import datetime -import sys -import os +import multiprocessing +from typing import List import time -from slips_files.common.idmefv2 import IDMEFv2 +from multiprocessing import Process from slips_files.common.style import ( green, ) from slips_files.common.parsers.config_parser import ConfigParser from slips_files.common.slips_utils import utils from slips_files.core.evidence_logger import EvidenceLogger -from slips_files.core.helpers.whitelist.whitelist import Whitelist -from slips_files.core.helpers.notify import Notify from slips_files.common.abstracts.icore import ICore -from slips_files.core.structures.evidence import ( - dict_to_evidence, - Evidence, - TimeWindow, -) -from slips_files.core.structures.alerts import ( - Alert, -) -from slips_files.core.text_formatters.evidence_formatter import ( - EvidenceFormatter, -) +from slips_files.core.evidence_handler_worker import EvidenceHandlerWorker -IS_IN_A_DOCKER_CONTAINER = os.environ.get("IS_IN_A_DOCKER_CONTAINER", False) + +DEFAULT_EVIDENCE_HANDLER_WORKERS = 3 # Evidence Process @@ -63,33 +44,18 @@ class EvidenceHandler(ICore): name = "EvidenceHandler" def init(self): - self.whitelist = Whitelist(self.logger, self.db, self.bloom_filters) - self.idmefv2 = IDMEFv2(self.logger, self.db) - self.separator = self.db.get_separator() self.read_configuration() - self.detection_threshold_in_this_width = ( - self.detection_threshold * self.width / 60 - ) # to keep track of the number of generated evidence self.db.init_evidence_number() - if self.popup_alerts: - self.notify = Notify() - if self.notify.bin_found: - # The way we send notifications differ depending - # on the user and the OS - self.notify.setup_notifications() - else: - self.popup_alerts = False - - self.is_running_non_stop = self.db.is_running_non_stop() - self.blocking_modules_supported = self.is_blocking_modules_supported() - - # this list will have our local and public ips when using -i - self.our_ips: List[str] = utils.get_own_ips(ret="List") - self.formatter = EvidenceFormatter(self.db, self.args) # thats just a tmp value, this variable will be set and used when # the module is stopping. self.last_msg_received_time = time.time() + # we don't want the workers to subscribe to channels and + # read from there, in that case all workers will process the same + # msg. instead we use a queue, so that each worker processes a + # unique msg. + self.evidence_worker_queue = multiprocessing.Queue(maxsize=30000000) + self.evidence_worker_child_processes: List[Process] = [] # A thread that handing I/O to disk (writing evidence to log files) self.logger_stop_signal = threading.Event() @@ -126,367 +92,51 @@ def read_configuration(self): 2, 0, ) - self.GID = conf.get_GID() - self.UID = conf.get_UID() - - self.popup_alerts = conf.popup_alerts() - # In docker, disable alerts no matter what slips.yaml says - if IS_IN_A_DOCKER_CONTAINER: - self.popup_alerts = False - - def handle_unable_to_log(self, failed_log, error=None): - self.print(f"Error logging evidence/alert: {error}. {failed_log}.") - - def add_alert_to_json_log_file(self, alert: Alert): - """ - Add a new alert/event line to our alerts.json file in json format. - """ - idmef_alert: dict = self.idmefv2.convert_to_idmef_alert(alert) - if not idmef_alert: - self.handle_unable_to_log(alert, "Can't convert to IDMEF alert") - return - - to_log = { - "to_log": idmef_alert, - "where": "alerts.json", - } - self.evidence_logger_q.put(to_log) - - def add_evidence_to_json_log_file( - self, - evidence, - accumulated_threat_level: float = 0, - ): - """ - Add a new evidence line to our alerts.json file in json format. - """ - idmef_evidence: dict = self.idmefv2.convert_to_idmef_event(evidence) - if not idmef_evidence: - self.handle_unable_to_log( - evidence, "Can't convert to IDMEF evidence" - ) - return - - try: - idmef_evidence.update( - { - "Note": json.dumps( - { - # this is all the uids of the flows that cause - # this evidence - "uids": evidence.uid, - "accumulated_threat_level": accumulated_threat_level, - "threat_level": str(evidence.threat_level), - "timewindow": evidence.timewindow.number, - } - ) - } - ) - - to_log = { - "to_log": idmef_evidence, - "where": "alerts.json", - } - - self.evidence_logger_q.put(to_log) - - except KeyboardInterrupt: - return True - except Exception as e: - self.handle_unable_to_log(evidence, e) - - def add_to_log_file(self, data: str): - """ - Add a new evidence line to the alerts.log and other log files if - logging is enabled. - """ - to_log = {"to_log": data, "where": "alerts.log"} - self.evidence_logger_q.put(to_log) - - def log_alert(self, alert: Alert, blocked=False): - """ - constructs the alert descript ion from the given alert and logs it - to alerts.log and alerts.json - :param blocked: bool. if the ip was blocked by the blocking module, - we should say so in alerts.log, if not, we should say that - we generated an alert - """ - now = utils.get_human_readable_datetime() - - alert_description = ( - f"{alert.last_flow_datetime}: " f"Src IP {alert.profile.ip:26}. " - ) - if blocked: - # Add to log files that this srcip is being blocked - alert_description += "Is blocked " - else: - alert_description += "Generated an alert " - - alert_description += ( - f"given enough evidence on timewindow " - f"{alert.timewindow.number}. (real time {now})" - ) - # log to alerts.log - self.add_to_log_file(alert_description) - # log to alerts.json - self.add_alert_to_json_log_file(alert) def shutdown_gracefully(self): + self.stop_evidence_workers() self.logger_stop_signal.set() try: self.logger_thread.join(timeout=5) except Exception: pass - def get_evidence_that_were_part_of_a_past_alert( - self, profileid: str, twid: str - ) -> List[str]: - """ - returns a list of evidence bool: - # given all the tw evidence, we should only - # consider evidence that makes this given - # profile malicious, aka evidence of this profile(srcip) attacking - # others. - return evidence.attacker.direction != "SRC" - - def get_evidence_for_tw( - self, profileid: str, twid: str - ) -> Optional[Dict[str, Evidence]]: - """ - filters and returns all the evidence for this profile in this TW - returns the dict with filtered evidence - """ - tw_evidence: Dict[str, dict] = self.db.get_twid_evidence( - profileid, twid - ) - if not tw_evidence: - return - - past_evidence_ids: List[str] = ( - self.get_evidence_that_were_part_of_a_past_alert(profileid, twid) - ) - - filtered_evidence = {} - - for id, evidence in tw_evidence.items(): - id: str - evidence: str - evidence: dict = json.loads(evidence) - evidence: Evidence = dict_to_evidence(evidence) - - if self.is_filtered_evidence(evidence, past_evidence_ids): - continue - - if self.db.is_whitelisted_evidence(id): - continue - - # delete not processed evidence - # sometimes the db has evidence that didn't come yet to evidence.py - # and they are alerted without checking the whitelist! - # to fix this, we keep track of processed evidence - # that came to new_evidence channel and were processed by it. - # so they are ready to be a part of an alert - profileid: str = str(evidence.profile) - if not self.db.is_evidence_processed(id, profileid, twid): - continue - - filtered_evidence[evidence.id] = evidence - - return filtered_evidence - - def is_filtered_evidence( - self, evidence: Evidence, past_evidence_ids: List[str] - ): - """ - filters the following - * evidence that were part of a past alert in this same profileid - twid (past_evidence_ids) - * evidence that weren't done by the given profileid - """ - - # delete already alerted evidence - # if there was an alert in this tw before, remove the evidence that - # were part of the past alert from the current evidence. - - # when blocking is not enabled, we can alert on a - # single profile many times - # when we get all the tw evidence from the db, we get the once we - # alerted, and the new once we need to alert - # this method removes the already alerted evidence to avoid duplicates - if evidence.id in past_evidence_ids: - return True - - if self.is_evidence_done_by_others(evidence): - return True - - return False - - def get_threat_level( - self, - evidence: Evidence, - ) -> float: - """ - return the threat level of the given evidence * confidence - """ - confidence: float = evidence.confidence - threat_level: float = evidence.threat_level.value - - # Compute the moving average of evidence - evidence_threat_level: float = threat_level * confidence - self.print( - f"\t\tWeighted Threat Level: " f"{evidence_threat_level}", 3, 0 - ) - return evidence_threat_level - - def send_to_exporting_module(self, tw_evidence: Dict[str, Evidence]): - """ - sends all given evidence to export_evidence channel - :param tw_evidence: all evidence that happened in a certain - timewindow - format is {evidence_id (str) : Evidence obj} - """ - for evidence in tw_evidence.values(): - evidence: Evidence - evidence_dict: dict = utils.to_dict(evidence) - self.print( - f"[EvidenceHandler] Exporting evidence {evidence_dict.get('id')} " - f"type={evidence_dict.get('evidence_type')} via export_evidence.", - 2, - 0, - ) - self.db.publish("export_evidence", json.dumps(evidence_dict)) - - def publish_single_evidence(self, evidence: Evidence): - evidence_dict: dict = utils.to_dict(evidence) - self.print( - f"[EvidenceHandler] Export streaming {evidence_dict.get('id')} " - f"type={evidence_dict.get('evidence_type')} via export_evidence.", - 2, - 0, - ) - self.db.publish("export_evidence", json.dumps(evidence_dict)) - - def is_blocking_modules_supported(self) -> bool: - """ - returns true if slips is running in an interface or growing - zeek dir with -p - or if slips is using custom flows (meaning slips is reading the - flows by a custom module not by input.py). - """ - custom_flows = "-im" in sys.argv or "--input-module" in sys.argv - blocking_module_enabled = "-p" in sys.argv - return ( - self.is_running_non_stop or custom_flows - ) and blocking_module_enabled - - def handle_new_alert( - self, - alert: Alert, - evidence_causing_the_alert, - ): - """ - saves alert details in the db and informs exporting modules about it - - if a profile already generated an alert in this tw, we send a - blocking request (to extend its blocking period), and log the alert - in the db only, without printing it to cli. - :param evidence_causing_the_alert: Dict[str, Evidence] - """ - self.db.set_alert(alert, evidence_causing_the_alert) - is_blocked: bool = self.decide_blocking( - alert.profile.ip, alert.timewindow - ) - # like in the firewall - profile_already_blocked: bool = self.db.is_blocked_profile_and_tw( - str(alert.profile), str(alert.timewindow) - ) - if profile_already_blocked: - # that's it, dont keep logging new alerts if 1 alerts is logged - # in this tw. - return - - self.send_to_exporting_module(evidence_causing_the_alert) - alert_to_print: str = self.formatter.format_evidence_for_printing( - alert, evidence_causing_the_alert - ) - - self.print(f"{alert_to_print}", 1, 0) - - if self.popup_alerts: - self.show_popup(alert) - - if is_blocked: - self.db.mark_profile_and_timewindow_as_blocked( - str(alert.profile), str(alert.timewindow) - ) - - self.log_alert(alert, blocked=is_blocked) - - def decide_blocking( - self, - ip_to_block: str, - timewindow: TimeWindow, - ) -> bool: - """ - Decide whether to block or not and send to the blocking module - returns True if the given IP was blocked by Slips blocking module - """ - # send ip to the blocking module - if not self.blocking_modules_supported: - return False - # now since this source ip(profileid) caused an alert, - # it means it caused so many evidence(attacked others a lot) - # that we decided to alert and block it - - # First, Make sure we don't block our own IP - if ip_to_block in self.our_ips: - return False - - # TODO: edit the options here. by default it'll block - # all traffic to or from this ip - # PS: if by default we don't block everything from/to this ip anymore, - # remember to update the CYST module - blocking_data = { - "ip": ip_to_block, - "block": True, - "tw": timewindow.number, - # in which localnet is this IP? to which interface does it belong? - "interface": utils.get_interface_of_ip( - ip_to_block, self.db, self.args - ), - } - blocking_data = json.dumps(blocking_data) - self.db.publish("new_blocking", blocking_data) - return True - - def update_accumulated_threat_level(self, evidence: Evidence) -> float: - """ - update the accumulated threat level of the profileid and twid of - the given evidence and return the updated value - """ - evidence_threat_level: float = self.get_threat_level(evidence) - return self.db.update_accumulated_threat_level( - str(evidence.profile), - str(evidence.timewindow), - evidence_threat_level, + used_queues = [ + self.evidence_worker_queue, + self.evidence_logger_q, + ] + + for q in used_queues: + q.cancel_join_thread() + q.close() + + def stop_evidence_workers(self): + for _ in self.evidence_worker_child_processes: + self.evidence_worker_queue.put("stop") + + for process in self.evidence_worker_child_processes: + try: + process.join() + except (OSError, ChildProcessError): + pass + + def start_evidence_worker(self, worker_id: int = None): + worker_name = f"EvidenceHandlerWorker_Process_{worker_id}" + worker = EvidenceHandlerWorker( + logger=self.logger, + output_dir=self.output_dir, + redis_port=self.redis_port, + termination_event=self.termination_event, + conf=self.conf, + ppid=self.ppid, + slips_args=self.args, + bloom_filters_manager=self.bloom_filters, + name=worker_name, + evidence_queue=self.evidence_worker_queue, + evidence_logger_q=self.evidence_logger_q, ) - - def show_popup(self, alert: Alert): - alert_description: str = self.formatter.get_printable_alert(alert) - self.notify.show_popup(alert_description) + worker.start() + self.evidence_worker_child_processes.append(worker) def should_stop(self) -> bool: """ @@ -512,161 +162,23 @@ def should_stop(self) -> bool: def pre_main(self): self.print(f"Using threshold: {green(self.detection_threshold)}") + for worker_id in range(DEFAULT_EVIDENCE_HANDLER_WORKERS): + self.start_evidence_worker(worker_id) def main(self): while not self.should_stop(): if msg := self.get_msg("evidence_added"): - msg["data"]: str - evidence: dict = json.loads(msg["data"]) - try: - evidence: Evidence = dict_to_evidence(evidence) - except Exception as e: - self.print( - f"Problem converting {evidence} to dict: " f"{e}", 0, 1 - ) - continue - profileid: str = str(evidence.profile) - twid: str = str(evidence.timewindow) - timestamp: str = evidence.timestamp - - # the database naturally has evidence before they reach - # this module. and sometime when this module queries - # evidence for a specific timewindow, the db returns all - # evidence including the ones the werent processed here yet. - # this marking of ev. as processed is to avoid that. - # so that get_evidence_for_tw() call below won't return - # unprocessed evidence. - self.db.mark_evidence_as_processed( - evidence.id, profileid, twid - ) - - if self.whitelist.is_whitelisted_evidence(evidence): - self.db.cache_whitelisted_evidence_id(evidence.id) - # Modules add evidence to the db before - # reaching this point, now remove evidence from db so - # it could be completely ignored - self.db.delete_evidence(profileid, twid, evidence.id) - self.print( - f"{self.whitelist.get_bloom_filters_stats()}", 2, 0 - ) - continue - - # convert time to local timezone - if self.is_running_non_stop: - timestamp: datetime = utils.convert_to_local_timezone( - timestamp - ) - flow_datetime = utils.convert_ts_format(timestamp, "iso") - - evidence: Evidence = ( - self.formatter.add_threat_level_to_evidence_description( - evidence - ) + self.evidence_worker_queue.put( + { + "channel": "evidence_added", + "message": msg, + } ) - evidence_to_log: str = self.formatter.get_evidence_to_log( - evidence, - flow_datetime, - ) - # Add the evidence to alerts.log - self.add_to_log_file(evidence_to_log) - - past_evidence_ids: List[str] = ( - self.get_evidence_that_were_part_of_a_past_alert( - profileid, twid - ) - ) - # filtered evidence dont add to the acc threat level - if not self.is_filtered_evidence(evidence, past_evidence_ids): - accumulated_threat_level: float = ( - self.update_accumulated_threat_level(evidence) - ) - else: - accumulated_threat_level: float = ( - self.db.get_accumulated_threat_level(profileid, twid) - ) - - # add to alerts.json - self.add_evidence_to_json_log_file( - evidence, - accumulated_threat_level, - ) - - # stream every evidence toward exporting modules immediately - self.publish_single_evidence(evidence) - - evidence_dict: dict = utils.to_dict(evidence) - self.db.publish("report_to_peers", json.dumps(evidence_dict)) - - # This is the part to detect if the accumulated - # evidence was enough for generating a detection - # The detection should be done in attacks per minute. - # The parameter in the configuration - # is attacks per minute - # So find out how many attacks corresponds - # to the width we are using - if ( - accumulated_threat_level - >= self.detection_threshold_in_this_width - ): - tw_evidence: Dict[str, Evidence] - tw_evidence = self.get_evidence_for_tw(profileid, twid) - if tw_evidence: - tw_start, tw_end = self.db.get_tw_limits( - profileid, twid - ) - evidence.timewindow.start_time = tw_start - evidence.timewindow.end_time = tw_end - - alert: Alert = Alert( - profile=evidence.profile, - timewindow=evidence.timewindow, - last_evidence=evidence, - accumulated_threat_level=accumulated_threat_level, - correl_id=list(tw_evidence.keys()), - ) - self.handle_new_alert(alert, tw_evidence) - if msg := self.get_msg("new_blame"): - data = msg["data"] - try: - data = json.loads(data) - except json.decoder.JSONDecodeError: - self.print( - "Error in the report received from p2ptrust module" - ) - return - # The available values for the following variables are - # defined in go_director - - # available key types: "ip" - # key_type = data['key_type'] - - # if the key type is ip, the ip is validated - key = data["key"] - - # available evaluation types: 'score_confidence' - # evaluation_type = data['evaluation_type'] - - # this is the score_confidence received from the peer - evaluation = data["evaluation"] - # {"key_type": "ip", "key": "1.2.3.40", - # "evaluation_type": "score_confidence", - # "evaluation": { "score": 0.9, "confidence": 0.6 }} - ip_info = {"p2p4slips": evaluation} - ip_info["p2p4slips"].update({"ts": time.time()}) - self.db.store_blame_report(key, evaluation) - - blocking_data = { - "ip": key, - "block": True, - "to": True, - "from": True, - # in which localnet is this IP? - # to which interface does it belong? - "interface": utils.get_interface_of_ip( - key, self.db, self.args - ), - } - blocking_data = json.dumps(blocking_data) - self.db.publish("new_blocking", blocking_data) + self.evidence_worker_queue.put( + { + "channel": "new_blame", + "message": msg, + } + ) diff --git a/slips_files/core/evidence_handler_worker.py b/slips_files/core/evidence_handler_worker.py new file mode 100644 index 0000000000..5ffa395b40 --- /dev/null +++ b/slips_files/core/evidence_handler_worker.py @@ -0,0 +1,512 @@ +# SPDX-FileCopyrightText: 2021 Sebastian Garcia +# SPDX-License-Identifier: GPL-2.0-only +# Stratosphere Linux IPS. A machine-learning Intrusion Detection System +# Copyright (C) 2021 Sebastian Garcia + +import json +import os +import queue +import sys +from multiprocessing import Queue +from typing import Dict, List, Optional + +from slips_files.common.abstracts.imodule import IModule +from slips_files.common.idmefv2 import IDMEFv2 +from slips_files.common.parsers.config_parser import ConfigParser +from slips_files.common.slips_utils import utils +from slips_files.common.style import green +from slips_files.core.helpers.notify import Notify +from slips_files.core.helpers.whitelist.whitelist import Whitelist +from slips_files.core.structures.alerts import Alert +from slips_files.core.structures.evidence import ( + Evidence, + ThreatLevel, + TimeWindow, + dict_to_evidence, +) +from slips_files.core.text_formatters.evidence_formatter import ( + EvidenceFormatter, +) + +IS_IN_A_DOCKER_CONTAINER = os.environ.get("IS_IN_A_DOCKER_CONTAINER", False) + + +class EvidenceHandlerWorker(IModule): + name = "EvidenceHandlerWorker" + + def init( + self, + name: str, + evidence_queue: Queue, + evidence_logger_q: Queue, + ): + self.name = name + self.evidence_queue = evidence_queue + self.evidence_logger_q = evidence_logger_q + self.whitelist = Whitelist(self.logger, self.db, self.bloom_filters) + self.idmefv2 = IDMEFv2(self.logger, self.db) + self.read_configuration() + self.detection_threshold_in_this_width = ( + self.detection_threshold * self.width / 60 + ) + if self.popup_alerts: + self.notify = Notify() + if self.notify.bin_found: + self.notify.setup_notifications() + else: + self.popup_alerts = False + + self.is_running_non_stop = self.db.is_running_non_stop() + self.blocking_modules_supported = self.is_blocking_modules_supported() + self.our_ips: List[str] = utils.get_own_ips(ret="List") + self.formatter = EvidenceFormatter(self.db, self.args) + self.slips_start_time: str = self.db.get_slips_start_time() + self.first_flow_pcap_time = None + + def subscribe_to_channels(self): + self.channels = {} + + def read_configuration(self): + conf = ConfigParser() + self.width: float = conf.get_tw_width_in_seconds() + self.detection_threshold = conf.evidence_detection_threshold() + self.print( + f"Detection Threshold: {self.detection_threshold} " + f"attacks per minute " + f"({self.detection_threshold * int(self.width) / 60} " + f"in the current time window width)", + 2, + 0, + ) + self.popup_alerts = conf.popup_alerts() + self.use_p2p: bool = conf.use_local_p2p() or conf.use_global_p2p() + self.exporting_modules_enabled: bool = ( + conf.export_to() or conf.send_to_warden() + ) + self.generate_performance_plots = ( + conf.generate_performance_plots() is True + ) + if IS_IN_A_DOCKER_CONTAINER: + self.popup_alerts = False + + def handle_unable_to_log(self, failed_log, error=None): + self.print(f"Error logging evidence/alert: {error}. {failed_log}.") + + def add_alert_to_json_log_file(self, alert: Alert): + idmef_alert: dict = self.idmefv2.convert_to_idmef_alert(alert) + if not idmef_alert: + self.handle_unable_to_log(alert, "Can't convert to IDMEF alert") + return + + self.evidence_logger_q.put( + { + "to_log": idmef_alert, + "where": "alerts.json", + } + ) + + def add_evidence_to_json_log_file( + self, + evidence: Evidence, + accumulated_threat_level: float = 0, + ): + idmef_evidence: dict = self.idmefv2.convert_to_idmef_event(evidence) + if not idmef_evidence: + self.handle_unable_to_log( + evidence, "Can't convert to IDMEF evidence" + ) + return + + try: + idmef_evidence.update( + { + "Note": json.dumps( + { + "uids": evidence.uid, + "accumulated_threat_level": accumulated_threat_level, + "threat_level": str(evidence.threat_level), + "timewindow": evidence.timewindow.number, + } + ) + } + ) + self.add_latency_to_csv(idmef_evidence) + self.evidence_logger_q.put( + { + "to_log": idmef_evidence, + "where": "alerts.json", + } + ) + except KeyboardInterrupt: + return True + except Exception as error: + self.handle_unable_to_log(evidence, error) + + def add_latency_to_csv(self, idmef_evidence: dict): + if not self.generate_performance_plots: + return + + start_time = idmef_evidence.get("StartTime") + create_time = idmef_evidence.get("CreateTime") + evidence_id = idmef_evidence.get("ID") + if not (start_time and create_time and evidence_id): + return + + if self.first_flow_pcap_time is None: + self.first_flow_pcap_time = float(self.db.get_first_flow_time()) + + try: + start_unix = utils.convert_ts_format(start_time, "unixtimestamp") + create_unix = utils.convert_ts_format(create_time, "unixtimestamp") + + if self.is_running_non_stop: + latency = float(create_unix) - float(start_unix) + else: + wall_elapsed = float(create_unix) - float( + self.slips_start_time + ) + pcap_elapsed = float(start_unix) - float( + self.first_flow_pcap_time + ) + latency = wall_elapsed - pcap_elapsed + if latency < 0: + latency = 0 + + latency = round(latency) + except Exception: + return + + self.evidence_logger_q.put( + { + "to_log": { + "ts": create_unix, + "evidence_id": evidence_id, + "latency": latency, + }, + "where": "latency.csv", + } + ) + + def add_to_log_file(self, data: str): + self.evidence_logger_q.put({"to_log": data, "where": "alerts.log"}) + + def log_alert(self, alert: Alert, blocked=False): + now = utils.get_human_readable_datetime() + + alert_description = ( + f"{alert.last_flow_datetime}: " f"Src IP {alert.profile.ip:26}. " + ) + if blocked: + alert_description += "Is blocked " + else: + alert_description += "Generated an alert " + + alert_description += ( + f"given enough evidence on timewindow " + f"{alert.timewindow.number}. (real time {now})" + ) + self.add_to_log_file(alert_description) + self.add_alert_to_json_log_file(alert) + + def get_evidence_that_were_part_of_a_past_alert( + self, profileid: str, twid: str + ) -> List[str]: + past_alerts: dict = self.db.get_profileid_twid_alerts(profileid, twid) + + past_evidence_ids = [] + if past_alerts: + for evidence_id_list in list(past_alerts.values()): + evidence_id_list: List[str] = json.loads(evidence_id_list) + past_evidence_ids += evidence_id_list + + return past_evidence_ids + + def is_evidence_done_by_others(self, evidence: Evidence) -> bool: + return evidence.attacker.direction != "SRC" + + def get_evidence_for_tw( + self, profileid: str, twid: str + ) -> Optional[Dict[str, Evidence]]: + tw_evidence: Dict[str, dict] = self.db.get_twid_evidence( + profileid, twid + ) + if not tw_evidence: + return None + + past_evidence_ids = self.get_evidence_that_were_part_of_a_past_alert( + profileid, twid + ) + filtered_evidence = {} + + for evidence_id, raw_evidence in tw_evidence.items(): + evidence = dict_to_evidence(json.loads(raw_evidence)) + + if self.is_filtered_evidence(evidence, past_evidence_ids): + continue + + if self.db.is_whitelisted_evidence(evidence_id): + continue + + profileid = str(evidence.profile) + if not self.db.is_evidence_processed(evidence_id, profileid, twid): + continue + + filtered_evidence[evidence.id] = evidence + + return filtered_evidence + + def is_filtered_evidence( + self, evidence: Evidence, past_evidence_ids: List[str] + ): + if evidence.id in past_evidence_ids: + return True + + if self.is_evidence_done_by_others(evidence): + return True + + return False + + def get_threat_level(self, evidence: Evidence) -> float: + evidence_threat_level = ( + evidence.threat_level.value * evidence.confidence + ) + self.print(f"\t\tWeighted Threat Level: {evidence_threat_level}", 3, 0) + return evidence_threat_level + + def send_to_exporting_module(self, tw_evidence: Dict[str, Evidence]): + if not self.exporting_modules_enabled: + return + + for evidence in tw_evidence.values(): + evidence_dict: dict = utils.to_dict(evidence) + self.print( + f"[EvidenceHandler] Exporting evidence {evidence_dict.get('id')} " + f"type={evidence_dict.get('evidence_type')} via export_evidence.", + 2, + 0, + ) + self.db.publish("export_evidence", json.dumps(evidence_dict)) + + def give_evidence_to_exporting_modules(self, evidence: Evidence): + if not self.exporting_modules_enabled: + return + + evidence_dict: dict = utils.to_dict(evidence) + self.print( + f"[EvidenceHandler] Export streaming {evidence_dict.get('id')} " + f"type={evidence_dict.get('evidence_type')} via export_evidence.", + 2, + 0, + ) + self.db.publish("export_evidence", json.dumps(evidence_dict)) + + def is_blocking_modules_supported(self) -> bool: + custom_flows = "-im" in sys.argv or "--input-module" in sys.argv + blocking_module_enabled = "-p" in sys.argv + return ( + self.is_running_non_stop or custom_flows + ) and blocking_module_enabled + + def handle_new_alert( + self, + alert: Alert, + evidence_causing_the_alert, + ): + self.db.set_alert(alert, evidence_causing_the_alert) + is_blocked: bool = self.decide_blocking( + alert.profile.ip, alert.timewindow + ) + profile_already_blocked: bool = self.db.is_blocked_profile_and_tw( + str(alert.profile), str(alert.timewindow) + ) + if profile_already_blocked: + return + + self.send_to_exporting_module(evidence_causing_the_alert) + alert_to_print: str = self.formatter.format_evidence_for_printing( + alert, evidence_causing_the_alert + ) + self.print(f"{alert_to_print}", 1, 0) + + if self.popup_alerts: + self.show_popup(alert) + + if is_blocked: + self.db.mark_profile_and_timewindow_as_blocked( + str(alert.profile), str(alert.timewindow) + ) + + self.log_alert(alert, blocked=is_blocked) + + def decide_blocking( + self, + ip_to_block: str, + timewindow: TimeWindow, + ) -> bool: + if not self.blocking_modules_supported: + return False + + if ip_to_block in self.our_ips: + return False + + blocking_data = { + "ip": ip_to_block, + "block": True, + "tw": timewindow.number, + "interface": utils.get_interface_of_ip( + ip_to_block, self.db, self.args + ), + } + self.db.publish("new_blocking", json.dumps(blocking_data)) + return True + + def update_accumulated_threat_level(self, evidence: Evidence) -> float: + evidence_threat_level = self.get_threat_level(evidence) + return self.db.update_accumulated_threat_level( + str(evidence.profile), + str(evidence.timewindow), + evidence_threat_level, + ) + + def show_popup(self, alert: Alert): + alert_description = self.formatter.get_printable_alert(alert) + self.notify.show_popup(alert_description) + + def get_accumulated_threat_level( + self, profileid, twid, evidence: Evidence + ) -> float: + if evidence.threat_level == ThreatLevel.INFO: + return self.db.get_accumulated_threat_level(profileid, twid) + + past_evidence_ids = self.get_evidence_that_were_part_of_a_past_alert( + profileid, twid + ) + if not self.is_filtered_evidence(evidence, past_evidence_ids): + return self.update_accumulated_threat_level(evidence) + + return self.db.get_accumulated_threat_level(profileid, twid) + + def get_msg_from_queue(self, q: Queue): + try: + return q.get(timeout=1) + except queue.Empty: + return None + except Exception: + return None + + def is_stop_msg(self, msg) -> bool: + return msg == "stop" + + def pre_main(self): + worker_number = self.name.split("_")[-1] + worker_name = f"Evidence Handler Worker {worker_number}" + self.print(f"Started {green(worker_name)} [PID {green(os.getpid())}]") + + def should_stop(self) -> bool: + return False + + def handle_evidence_added_message(self, msg: dict): + evidence = json.loads(msg["data"]) + try: + evidence = dict_to_evidence(evidence) + except Exception as error: + self.print(f"Problem converting {evidence} to dict: {error}", 0, 1) + return + + profileid = str(evidence.profile) + twid = str(evidence.timewindow) + timestamp = evidence.timestamp + + self.db.mark_evidence_as_processed(evidence.id, profileid, twid) + + if self.whitelist.is_whitelisted_evidence(evidence): + self.db.cache_whitelisted_evidence_id(evidence.id) + self.db.delete_evidence(profileid, twid, evidence.id) + self.print(f"{self.whitelist.get_bloom_filters_stats()}", 2, 0) + return + + if self.is_running_non_stop: + timestamp = utils.convert_to_local_timezone(timestamp) + flow_datetime = utils.convert_ts_format(timestamp, "iso") + + evidence = self.formatter.add_threat_level_to_evidence_description( + evidence + ) + evidence_to_log = self.formatter.get_evidence_to_log( + evidence, + flow_datetime, + ) + self.add_to_log_file(evidence_to_log) + + accumulated_threat_level = self.get_accumulated_threat_level( + profileid, twid, evidence + ) + self.add_evidence_to_json_log_file( + evidence, + accumulated_threat_level, + ) + self.give_evidence_to_exporting_modules(evidence) + + if self.use_p2p: + self.db.publish( + "report_to_peers", json.dumps(utils.to_dict(evidence)) + ) + + if accumulated_threat_level < self.detection_threshold_in_this_width: + return + + tw_evidence = self.get_evidence_for_tw(profileid, twid) + if not tw_evidence: + return + + tw_start, tw_end = self.db.get_tw_limits(profileid, twid) + evidence.timewindow.start_time = tw_start + evidence.timewindow.end_time = tw_end + + alert = Alert( + profile=evidence.profile, + timewindow=evidence.timewindow, + last_evidence=evidence, + accumulated_threat_level=accumulated_threat_level, + correl_id=list(tw_evidence.keys()), + ) + self.handle_new_alert(alert, tw_evidence) + + def handle_new_blame_message(self, msg: dict): + data = msg["data"] + try: + data = json.loads(data) + except json.decoder.JSONDecodeError: + self.print("Error in the report received from p2ptrust module") + return + + key = data["key"] + evaluation = data["evaluation"] + self.db.store_blame_report(key, evaluation) + + blocking_data = { + "ip": key, + "block": True, + "to": True, + "from": True, + "interface": utils.get_interface_of_ip(key, self.db, self.args), + } + self.db.publish("new_blocking", json.dumps(blocking_data)) + + def main(self): + """runs in a loop defined in IModule""" + task = self.get_msg_from_queue(self.evidence_queue) + if not task: + return + + if self.is_stop_msg(task): + self.print("Received stop signal. Stopping.") + return 1 + + channel = task["channel"] + msg = task["message"] + + if channel == "evidence_added": + self.handle_evidence_added_message(msg) + elif channel == "new_blame": + self.handle_new_blame_message(msg) diff --git a/slips_files/core/evidence_logger.py b/slips_files/core/evidence_logger.py index 7b548f7348..e1308aa781 100644 --- a/slips_files/core/evidence_logger.py +++ b/slips_files/core/evidence_logger.py @@ -1,10 +1,13 @@ +import csv import json import os import queue import threading import traceback +import multiprocessing from slips_files.common.parsers.config_parser import ConfigParser +from slips_files.common.performance_paths import get_performance_csv_path from slips_files.common.slips_utils import utils @@ -12,7 +15,7 @@ class EvidenceLogger: def __init__( self, logger_stop_signal: threading.Event, - evidence_logger_q: queue.Queue, + evidence_logger_q: multiprocessing.Queue, output_dir: str, ): self.logger_stop_signal = logger_stop_signal @@ -26,17 +29,43 @@ def __init__( # clear output/alerts.json self.jsonfile = self.clean_file(self.output_dir, "alerts.json") utils.change_logfiles_ownership(self.jsonfile.name, self.UID, self.GID) + self.latency_file = None + self.latency_writer = None + if self.generate_performance_plots: + self._init_latency_file() def read_configuration(self): conf = ConfigParser() self.GID = conf.get_GID() self.UID = conf.get_UID() + self.generate_performance_plots = ( + conf.generate_performance_plots() is True + ) + + def _init_latency_file(self): + self.latency_file = self.clean_file( + self.output_dir, + get_performance_csv_path(self.output_dir, "latency.csv"), + ) + utils.change_logfiles_ownership( + self.latency_file.name, self.UID, self.GID + ) + self.latency_writer = csv.writer(self.latency_file) + self.latency_writer.writerow(["ts", "evidence_id", "latency"]) + self.latency_file.flush() def clean_file(self, output_dir, file_to_clean): """ Clear the file if exists and return an open handle to it """ - logfile_path = os.path.join(output_dir, file_to_clean) + if os.path.isabs(file_to_clean): + logfile_path = file_to_clean + else: + logfile_path = os.path.join(output_dir, file_to_clean) + + logfile_dir = os.path.dirname(logfile_path) + if logfile_dir: + os.makedirs(logfile_dir, exist_ok=True) if os.path.exists(logfile_path): open(logfile_path, "w").close() return open(logfile_path, "a") @@ -68,6 +97,21 @@ def print_to_alerts_json(self, idmef_evidence: dict): except Exception: return + def print_to_latency_csv(self, row: dict): + if self.latency_writer is None or self.latency_file is None: + return + + try: + self.latency_writer.writerow( + [row["ts"], row["evidence_id"], row["latency"]] + ) + self.latency_file.flush() # flush Python buffer + os.fsync(self.latency_file.fileno()) # flush OS buffer + except KeyboardInterrupt: + return True + except Exception: + return + def run_logger_thread(self): """ runs forever in a loop reveiving msgs from evidence_handler and @@ -76,12 +120,16 @@ def run_logger_thread(self): happening, so slips can process evidence faster there while we log as fast as possible here """ - while not self.logger_stop_signal.is_set(): + while True: try: msg = self.evidence_logger_q.get(timeout=1) except queue.Empty: + if self.logger_stop_signal.is_set(): + break continue except Exception: + if self.logger_stop_signal.is_set(): + break continue destination = msg["where"] @@ -91,9 +139,13 @@ def run_logger_thread(self): elif destination == "alerts.json": self.print_to_alerts_json(msg["to_log"]) + elif destination == "latency.csv": + self.print_to_latency_csv(msg["to_log"]) self.shutdown_gracefully() def shutdown_gracefully(self): self.logfile.close() self.jsonfile.close() + if self.latency_file is not None: + self.latency_file.close() diff --git a/slips_files/core/helpers/localnet_cache.py b/slips_files/core/helpers/localnet_cache.py deleted file mode 100644 index a51819e505..0000000000 --- a/slips_files/core/helpers/localnet_cache.py +++ /dev/null @@ -1,48 +0,0 @@ -import json -import multiprocessing -from typing import Dict, List, Tuple - - -class LocalnetCacheShared: - """Small shared dict cache stored as JSON in shared memory.""" - - def __init__(self, size: int = 8192) -> None: - self.size = size - self.buffer = multiprocessing.Array("c", size, lock=False) - self.lock = multiprocessing.Lock() - # ensure buffer is nul-terminated - self.buffer[:] = b"\x00" * size - - def _read_bytes(self) -> bytes: - raw = bytes(self.buffer[:]) - try: - end = raw.index(0) - except ValueError: - end = len(raw) - return raw[:end] - - def get(self) -> Dict[str, str]: - with self.lock: - raw = self._read_bytes() - if not raw: - return {} - try: - return json.loads(raw.decode("utf-8")) - except json.JSONDecodeError: - return {} - - def contains(self, key: str) -> bool: - return key in self.get() - - def items(self) -> List[Tuple[str, str]]: - return list(self.get().items()) - - def set(self, new_cache: Dict[str, str]) -> bool: - payload = json.dumps(new_cache, separators=(",", ":")).encode("utf-8") - if len(payload) >= self.size: - # refuse to write partial data - return False - with self.lock: - self.buffer[: len(payload)] = payload - self.buffer[len(payload) :] = b"\x00" * (self.size - len(payload)) - return True diff --git a/slips_files/core/helpers/localnet_handler.py b/slips_files/core/helpers/localnet_handler.py new file mode 100644 index 0000000000..fd0a654c07 --- /dev/null +++ b/slips_files/core/helpers/localnet_handler.py @@ -0,0 +1,166 @@ +import ipaddress +from ipaddress import IPv4Address, IPv4Network, IPv6Address, IPv6Network +from typing import Dict, List, Union +import validators + +import netifaces + +from slips_files.common.slips_utils import utils + + +class LocalnetHandler: + def __init__(self, profiler) -> None: + self.profiler = profiler + self._private_client_ips = self.get_private_client_ips( + self.profiler.client_ips + ) + self._configured_default_localnet = ( + self._get_configured_default_localnet() + ) + self.is_running_non_stop = self.profiler.db.is_running_non_stop() + self.done_recognizing_all_localnets = False + self.localnet_cache = {} + self.number_of_expected_localnets: int = ( + self._get_expected_localnets_number() + ) + + def get_private_client_ips( + self, client_ips=None + ) -> List[Union[IPv4Network, IPv6Network, IPv4Address, IPv6Address]]: + """ + returns the private ips found in the client_ips param + in the config file + """ + if client_ips is None: + client_ips = self.profiler.client_ips + + try: + ips = list(client_ips) + except TypeError: + return [] + + private_clients = [] + for ip in ips: + if utils.is_private_ip(ip): + private_clients.append(ip) + return private_clients + + def _get_configured_default_localnet(self) -> Dict[str, str]: + """if private client_ips are set in the config, derive the used + local net from it""" + for range_ in self._private_client_ips: + if isinstance(range_, (IPv4Network, IPv6Network)): + return {"default": str(range_)} + return {} + + def _get_localnet_of_given_interfaces_using_netifaces( + self, + ) -> Dict[str, str]: + """ + returns the local network of the given interface/s (-i or -ap) + """ + local_nets = {} + for interface in utils.get_all_interfaces(self.profiler.args): + addrs = netifaces.ifaddresses(interface).get(netifaces.AF_INET) + if not addrs: + return local_nets + + for addr in addrs: + ip = addr.get("addr") + netmask = addr.get("netmask") + if ip and netmask: + network = ipaddress.IPv4Network( + f"{ip}/{netmask}", strict=False + ) + local_nets[interface] = str(network) + return local_nets + + def _get_local_net_of_flow(self, flow) -> Dict[str, str]: + """ + gets the local network from client_ip + param in the config file, + or by using the localnetwork of the first private + srcip seen in the traffic + """ + if self._configured_default_localnet: + return self._configured_default_localnet.copy() + + ip: str = flow.saddr + if cidr := utils.get_cidr_of_private_ip(ip): + return {"default": cidr} + + return {} + + def _get_expected_localnets_number(self): + """ + if using -ap, we expect 2localnets,one for eeach interface, + if using -i, we expect 1 + """ + return 2 if self.profiler.args.access_point else 1 + + def handle_setting_local_net(self, flow): + """ + stores the local network if possible + sets the self.localnet_cache dict + """ + if not self._should_set_localnet(flow): + return + + if self.is_running_non_stop: + local_nets: Dict[str, str] = ( + self._get_localnet_of_given_interfaces_using_netifaces() + ) + else: + # slips is analyzing a file + local_nets: Dict[str, str] = self._get_local_net_of_flow(flow) + + self.localnet_cache = local_nets + + for interface, local_net in self.localnet_cache.items(): + self.profiler.db.set_local_network(local_net, interface) + + def _should_set_localnet(self, flow) -> bool: + """ + returns true only if the saddr of the current flow is ipv4, private + and we don't have the local_net set already + """ + if self.done_recognizing_all_localnets: + return False + + if ( + self.profiler.db.get_total_recognized_localnets() + == self.number_of_expected_localnets + ): + self.done_recognizing_all_localnets = True + return False + + if self.is_running_non_stop: + if flow.interface in self.localnet_cache: + # localnet of this interface is already recognized + return False + + elif "default" in self.localnet_cache: + # slips is analyzing a pcap/zeek dir, and we already guessed the + # localnet of it + return False + + if flow.saddr == "0.0.0.0": + return False + + if self._private_client_ips: + return True + + if not validators.ipv4(flow.saddr): + return False + + saddr_obj = ipaddress.ip_address(flow.saddr) + + if ( + saddr_obj.is_multicast + or saddr_obj.is_link_local + or saddr_obj.is_loopback + or saddr_obj.is_reserved + or not saddr_obj.is_private + ): + return False + return True diff --git a/slips_files/core/input/input.py b/slips_files/core/input/input.py index d0a93925b4..7d2589326e 100644 --- a/slips_files/core/input/input.py +++ b/slips_files/core/input/input.py @@ -2,6 +2,7 @@ # SPDX-License-Identifier: GPL-2.0-only # Stratosphere Linux IPS. A machine-learning Intrusion Detection System # Copyright (C) 2021 Sebastian Garcia +import time # This program is free software; you can redistribute it and/or # modify it under the terms of the GNU General Public License @@ -126,12 +127,38 @@ def mark_self_as_done_processing(self): "Telling Profiler to stop because " "no more input is arriving.", log_to_logfiles_only=True, ) - number_of_profiler_workers: int = ( - self.db.get_profiler_workers_started() - ) - for _ in range(number_of_profiler_workers): + # ok this very terrible solution is to prevent the race condition + # that happens when the analyzed file is extremely small, that the + # input reads it, sends to the profiler queue, and reaches here, + # before the workers all start!! so we end up sending 0 stop msgs + # because 0 workers has started. this race condition causes slips + # to stay up forever waiting for stop msgs that will never be recvd + # in the profiler. + # this says " if the input took less than 3mins to reach this line, + # give slips extra 10s justt o make sure profilers are started + # before sending the stop msgs" + max_time_slips_can_take_to_start_all_processes = 60 * 3 + if ( + time.time() + < float(self.db.get_slips_start_time()) + + max_time_slips_can_take_to_start_all_processes + ): + self.print( + "Giving Slips time to start all profilers.", + log_to_logfiles_only=True, + ) + time.sleep(20) + + started_workers: int = self.db.get_profiler_workers_started() + self.print( + f"Sending {started_workers} stop " + f"signals for the profiler workers.", + log_to_logfiles_only=True, + ) + for _ in range(started_workers): self.profiler_queue.put("stop") + # this has to be done after the sentinel is put in the queue, # or else we'll have a deadlock when slips is stopping if self.is_input_done_event is not None: @@ -202,7 +229,7 @@ def shutdown_gracefully(self): try: self.active_handler.shutdown_gracefully() except Exception: - pass + self.print_traceback() return True @@ -214,6 +241,9 @@ def give_profiler(self, line): to_send = {"line": line, "input_type": self.input_type} # when the queue is full, it blocks forever until a free slot is # available + if self.conf.generate_performance_plots(): + # record the flow for per-minute stats + self.db.record_flow_per_minute("input") self.profiler_queue.put(to_send, block=True, timeout=None) def main(self): diff --git a/slips_files/core/input/zeek/zeek_dir_input.py b/slips_files/core/input/zeek/zeek_dir_input.py index a02673c211..5efa851b05 100644 --- a/slips_files/core/input/zeek/zeek_dir_input.py +++ b/slips_files/core/input/zeek/zeek_dir_input.py @@ -62,10 +62,9 @@ def run(self): continue if not growing_zeek_dir: - # get the total number of flows slips is going to read + # get the total number of flow in this file total_flows += self.input.get_flows_number(full_path) - # Add log file to the database self.db.add_zeek_file(full_path, interface) # in testing mode, we only need to read one zeek file to know @@ -79,9 +78,8 @@ def run(self): self.input.total_flows = total_flows self.db.set_input_metadata({"total_flows": total_flows}) - # needed in store_flows_read_per_second() + # keeps running until all zeek logs are over. self.input.lines = self.input.zeek_utils.read_zeek_files() - return True def shutdown_gracefully(self): diff --git a/slips_files/core/profiler.py b/slips_files/core/profiler.py index 90d5a52dc7..c7d8454625 100644 --- a/slips_files/core/profiler.py +++ b/slips_files/core/profiler.py @@ -41,7 +41,6 @@ from slips_files.core.input_profilers.suricata import Suricata from slips_files.core.input_profilers.zeek import ZeekJSON, ZeekTabs from slips_files.core.profiler_worker import ProfilerWorker -from slips_files.core.helpers.localnet_cache import LocalnetCacheShared SUPPORTED_INPUT_TYPES = { InputType.ZEEK: ZeekJSON, @@ -107,9 +106,6 @@ def init( # workers stoppped. self.did_all_workers_stop = multiprocessing.Event() self.last_worker_id = -1 - self.handle_setting_local_net_lock = multiprocessing.Lock() - # small, shared JSON cache backed by shared memory (no Manager) - self.localnet_cache = LocalnetCacheShared() # max parallel profiler workers to start when high throughput is detected self.max_workers = 6 # 30MBs max size of this queue to avoid growing forever in mem @@ -231,9 +227,7 @@ def start_profiler_worker(self, worker_id: int = None): bloom_filters_manager=self.bloom_filters, # module specific kwargs name=worker_name, - localnet_cache=self.localnet_cache, profiler_queue=self.profiler_queue, - handle_setting_local_net_lock=self.handle_setting_local_net_lock, input_handler=self.input_handler_obj, aid_queue=self.aid_queue, aid_manager=self.aid_manager, @@ -270,38 +264,39 @@ def get_handler_obj( return input_handler_cls def shutdown_gracefully(self): - # wait for all flows to be processed by the profiler processes. - self.stop_profiler_workers() - - self.aid_queue.put("stop") - self.stop_aid_manager_event.set() - self.aid_manager.shutdown() - - used_queues = [ - self.profiler_queue, - self.aid_queue, - ] - - for q in used_queues: - # By default if a process is not the creator of the queue then on - # exit it will attempt to join the queue’s background thread. The - # process can call cancel_join_thread() to make join_thread() - # do nothing. - q.cancel_join_thread() - - # close the queues to avoid deadlocks. - # this step SHOULD NEVER be done before closing the workers - q.close() - - if self.profiler_monitor_thread.is_alive(): - self.profiler_monitor_thread.join(timeout=5) - - self.print( - "Stopping.", - log_to_logfiles_only=True, - ) - self.mark_self_as_done_processing() - self.db.set_new_incoming_flows(False) + try: + # wait for all flows to be processed by the profiler processes. + self.stop_profiler_workers() + + self.aid_queue.put("stop") + self.stop_aid_manager_event.set() + self.aid_manager.shutdown() + + used_queues = [ + self.profiler_queue, + self.aid_queue, + ] + + for q in used_queues: + # By default if a process is not the creator of the queue then on + # exit it will attempt to join the queue’s background thread. The + # process can call cancel_join_thread() to make join_thread() + # do nothing. + q.cancel_join_thread() + + # close the queues to avoid deadlocks. + # this step SHOULD NEVER be done before closing the workers + q.close() + + if self.profiler_monitor_thread.is_alive(): + self.profiler_monitor_thread.join(timeout=5) + finally: + self.print( + "Stopping.", + log_to_logfiles_only=True, + ) + self.mark_self_as_done_processing() + self.db.set_new_incoming_flows(False) def did_5min_pass_since_last_throughput_check(self) -> bool: """ @@ -409,7 +404,7 @@ def main(self): utils.start_thread(self.profiler_monitor_thread, self.db) # slips starts with these workers by default until it detects # high throughput that these workers arent enough to handle - num_of_profiler_workers = 5 + num_of_profiler_workers = 3 for worker_id in range(num_of_profiler_workers): self.last_worker_id = worker_id self.start_profiler_worker(worker_id) diff --git a/slips_files/core/profiler_worker.py b/slips_files/core/profiler_worker.py index 0759816591..6edf1b8945 100644 --- a/slips_files/core/profiler_worker.py +++ b/slips_files/core/profiler_worker.py @@ -1,27 +1,28 @@ +import csv import json import os -from dataclasses import asdict -import ipaddress import pprint +import time +import ipaddress import multiprocessing +from dataclasses import asdict from typing import ( List, Union, Optional, - Dict, Callable, ) from ipaddress import IPv4Network, IPv6Network, IPv4Address, IPv6Address -import netifaces -import validators import gc from slips_files.common.abstracts.imodule import IModule from slips_files.common.slips_utils import utils +from slips_files.common.performance_paths import get_performance_csv_path from slips_files.common.style import green from slips_files.core.aid_manager import AIDManager from slips_files.core.helpers.flow_handler import FlowHandler +from slips_files.core.helpers.localnet_handler import LocalnetHandler from slips_files.core.helpers.symbols_handler import SymbolHandler from slips_files.core.helpers.whitelist.whitelist import Whitelist from slips_files.core.input_profilers.argus import Argus @@ -37,9 +38,7 @@ class ProfilerWorker(IModule): def init( self, name, - localnet_cache, profiler_queue: multiprocessing.Queue, - handle_setting_local_net_lock: multiprocessing.Lock, input_handler: ( ZeekTabs | ZeekJSON | Argus | Suricata | ZeekTabs | Nfdump ), @@ -58,10 +57,9 @@ def init( # this is an instance of # ZeekTabs | ZeekJSON | Argus | Suricata | ZeekTabs | Nfdump self.input_handler = input_handler - self.handle_setting_local_net_lock = handle_setting_local_net_lock self.read_configuration() self.received_lines = 0 - self.localnet_cache = localnet_cache + self.localnet_handler = LocalnetHandler(self) self.whitelist = Whitelist(self.logger, self.db, self.bloom_filters) self.symbol = SymbolHandler(self.logger, self.db) # stores the MAC addresses of the gateway of each interface @@ -71,6 +69,17 @@ def init( # flag to know which flow is the start of the pcap/file self.first_flow = True self.is_running_non_stop: bool = self.db.is_running_non_stop() + self.slips_start_time = self._get_slips_start_time() + self.latency_logfile = None + if self.generate_performance_plots: + self.latency_logfile = get_performance_csv_path( + self.output_dir, + f"{self._get_latency_filename_prefix()}_latency.csv", + ) + self._initialize_latency_logfile() + self._modified_tws = {} + self._time_to_update_modified_tws = time.time() + self._modified_timewindows_update_period = 3 # in seconds def subscribe_to_channels(self): self.c1 = self.db.subscribe("new_zeek_fields_line") @@ -88,6 +97,9 @@ def read_configuration(self): self.analysis_direction = self.conf.analysis_direction() self.label = self.conf.label() self.width = self.conf.get_tw_width_in_seconds() + self.generate_performance_plots = ( + self.conf.generate_performance_plots() is True + ) def get_msg_from_queue(self, q: multiprocessing.Queue): """ @@ -100,19 +112,6 @@ def get_msg_from_queue(self, q: multiprocessing.Queue): except Exception: return None - def get_private_client_ips( - self, - ) -> List[Union[IPv4Network, IPv6Network, IPv4Address, IPv6Address]]: - """ - returns the private ips found in the client_ips param - in the config file - """ - private_clients = [] - for ip in self.client_ips: - if utils.is_private_ip(ip): - private_clients.append(ip) - return private_clients - def convert_starttime_to_unix_ts(self, starttime) -> str: if utils.is_unix_ts(starttime): return starttime @@ -139,6 +138,71 @@ def store_first_seen_ts(self, ts): self.db.set_input_metadata({"file_start": ts}) + def _get_slips_start_time(self) -> float: + slips_start_time = self.db.get_slips_start_time() + try: + return float(slips_start_time) + except (TypeError, ValueError): + return time.time() + + def _get_latency_filename_prefix(self) -> str: + if self.name.startswith("ProfilerWorker_Process_"): + worker_id = self.name.split("_")[-1] + return f"profiler_worker_{worker_id}" + return self.name.lower() + + def _initialize_latency_logfile(self): + if not self.latency_logfile: + return + + os.makedirs(os.path.dirname(self.latency_logfile), exist_ok=True) + if os.path.exists(self.latency_logfile): + return + + with open( + self.latency_logfile, "w", newline="", encoding="utf-8" + ) as f: + writer = csv.writer(f) + writer.writerow( + ["timestamp_now", "flow_uid", "latency_in_seconds"] + ) + + def _log_flow_latency(self, flow, flow_starttime) -> None: + if not self.generate_performance_plots or not self.latency_logfile: + return + + try: + flow_start_ts = float(flow_starttime) + except (TypeError, ValueError): + return + + now = time.time() + timestamp_now = now - self.slips_start_time + latency = now - flow_start_ts + flow_uid = getattr(flow, "uid", "") + + with open( + self.latency_logfile, "a", newline="", encoding="utf-8" + ) as f: + writer = csv.writer(f) + writer.writerow([timestamp_now, flow_uid, int(latency)]) + + def _update_modified_tws_in_the_db(self, profileid: str, twid: str, flow): + """ + to avoid updating the modified tws in the db for every single flow, + we batch the updates and do them every 3 seconds + """ + self._modified_tws.update({f"{profileid}_{twid}": flow.starttime}) + now = time.time() + if now > self._time_to_update_modified_tws: + self._time_to_update_modified_tws = ( + now + self._modified_timewindows_update_period + ) + # now that slips successfully parsed the flow, + # mark this profile as modified + self.db.mark_profile_tw_as_modified(self._modified_tws) + self._modified_tws = {} + def store_features_going_in(self, profileid: str, twid: str, flow): """ If we have the all direction set , slips creates profiles @@ -167,10 +231,7 @@ def store_features_going_in(self, profileid: str, twid: str, flow): self.db.add_ips(profileid, twid, flow, role) # Add the flow with all the fields interpreted to the sqlite db self.aid_manager.submit_aid_task(flow, profileid, twid, self.label) - - # now that slips successfully parsed the flow, - # mark this profile as modified - self.db.mark_profile_tw_as_modified(profileid, twid, flow.starttime) + self._update_modified_tws_in_the_db(profileid, twid, flow) def get_aid_and_store_flow_in_the_db( self, @@ -246,7 +307,7 @@ def store_features_going_out(self, flow, profileid, twid): ) # now that slips successfully parsed the flow, # mark this profile as modified - self.db.mark_profile_tw_as_modified(profileid, twid, flow.starttime) + self._update_modified_tws_in_the_db(profileid, twid, flow) return True def get_rev_profile(self, flow): @@ -267,80 +328,6 @@ def get_rev_profile(self, flow): rev_twid: str = self.db.get_timewindow(flow.starttime, rev_profileid) return rev_profileid, rev_twid - def get_localnet_of_given_interface(self) -> Dict[str, str]: - """ - returns the local network of the given interface only if slips is - running with -i - """ - local_nets = {} - for interface in utils.get_all_interfaces(self.args): - addrs = netifaces.ifaddresses(interface).get(netifaces.AF_INET) - if not addrs: - return local_nets - - for addr in addrs: - ip = addr.get("addr") - netmask = addr.get("netmask") - if ip and netmask: - network = ipaddress.IPv4Network( - f"{ip}/{netmask}", strict=False - ) - local_nets[interface] = str(network) - return local_nets - - def get_local_net_of_flow(self, flow) -> Dict[str, str]: - """ - gets the local network from client_ip - param in the config file, - or by using the localnetwork of the first private - srcip seen in the traffic - """ - local_net = {} - # Reaching this func means slips is running on a file. we either - # have a client ip or not - private_client_ips: List[ - Union[IPv4Network, IPv6Network, IPv4Address, IPv6Address] - ] - # get_private_client_ips from the config file - if private_client_ips := self.get_private_client_ips(): - # does the client ip from the config already have the localnet? - for range_ in private_client_ips: - if isinstance(range_, IPv4Network) or isinstance( - range_, IPv6Network - ): - local_net["default"] = str(range_) - return local_net - - # For now the local network is only ipv4, but it - # could be ipv6 in the future. Todo. - ip: str = flow.saddr - if cidr := utils.get_cidr_of_private_ip(ip): - local_net["default"] = cidr - return local_net - - return local_net - - def handle_setting_local_net(self, flow): - """ - stores the local network if possible - sets the self.localnet_cache dict - """ - # this lock is to avoid running this func from the workers at the - # same time. - with self.handle_setting_local_net_lock: - if not self.should_set_localnet(flow): - return - - if self.db.is_running_non_stop(): - self._set_localnet_cache( - self.get_localnet_of_given_interface() - ) - else: - self._set_localnet_cache(self.get_local_net_of_flow(flow)) - - for interface, local_net in self._iter_localnet_cache_items(): - self.db.set_local_network(local_net, interface) - def is_gw_info_detected(self, info_type: str, interface: str) -> bool: """ checks own attributes and the db for the gw mac/ip @@ -466,72 +453,6 @@ def is_ignored_ip(self, ip: str) -> bool: or ip_obj.is_reserved ) - def should_set_localnet(self, flow) -> bool: - """ - returns true only if the saddr of the current flow is ipv4, private - and we don't have the local_net set already - """ - if self.db.is_running_non_stop(): - if self._localnet_cache_contains(flow.interface): - return False - elif self._localnet_cache_contains("default"): - # running on a file, impossible to get the interface - return False - - if flow.saddr == "0.0.0.0": - return False - - if self.get_private_client_ips(): - # if we have private client ips, we're ready to set the - # localnetwork - return True - - if not validators.ipv4(flow.saddr): - return False - - if self.is_ignored_ip(flow.saddr): - return False - - saddr_obj = ipaddress.ip_address(flow.saddr) - if not utils.is_private_ip(saddr_obj): - return False - - return True - - def _localnet_cache_contains(self, interface: str) -> bool: - """checks""" - cache = self.localnet_cache - if hasattr(cache, "contains"): - return cache.contains(interface) - try: - return interface in cache - except (AttributeError, TypeError): - self.localnet_cache = {} - return False - - def _iter_localnet_cache_items(self): - cache = self.localnet_cache - if hasattr(cache, "items"): - try: - return list(cache.items()) - except TypeError: - pass - if isinstance(cache, dict): - return list(cache.items()) - self.localnet_cache = {} - return [] - - def _set_localnet_cache(self, new_cache: Dict[str, str]) -> None: - cache = self.localnet_cache - if hasattr(cache, "set"): - if cache.set(new_cache): - return - if isinstance(cache, dict): - cache.clear() - cache.update(new_cache) - return - self.localnet_cache = new_cache - def _is_supported_flow_type(self, flow) -> bool: supported_types = ( "ssh", @@ -575,6 +496,9 @@ def add_flow_to_profile(self, flow): # software and weird.log flows are allowed to not have a daddr return False + flow_starttime = self.convert_starttime_to_unix_ts(flow.starttime) + self._log_flow_latency(flow, flow_starttime) + self.get_gateway_info(flow) # Check if the flow is whitelisted and we should not process it if self.whitelist.is_whitelisted_flow(flow): @@ -586,13 +510,13 @@ def add_flow_to_profile(self, flow): # in this tw for this profile profileid = f"profile_{flow.saddr}" self.print(f"Storing data in the profile: {profileid}", 3, 0) - flow.starttime = self.convert_starttime_to_unix_ts(flow.starttime) + flow.starttime = flow_starttime # Create profiles for all ips we see self.db.add_profile(profileid, flow.starttime) # For this 'forward' profile, find the id in the - # database of the tw where the flow belongs. n = time.time() + # database of the tw where the flow belongs. twid = self.db.get_timewindow(flow.starttime, profileid) self.store_features_going_out(flow, profileid, twid) @@ -657,11 +581,6 @@ def main(self): msg = self.get_msg_from_queue(self.profiler_queue) if not msg: - if ( - self.is_input_done_event is not None - and self.is_input_done_event.is_set() - ): - return 1 return if self.is_stop_msg(msg): @@ -689,9 +608,12 @@ def main(self): return self.add_flow_to_profile(flow) - self.handle_setting_local_net(flow) + self.localnet_handler.handle_setting_local_net(flow) self.db.increment_processed_flows() + if self.generate_performance_plots: + self.db.record_flow_per_minute(self.name) + # manually run garbage collection to avoid the latency # introduced by it when slips is given a huge number of flows if self.received_lines % 10000 == 0: diff --git a/tests/module_factory.py b/tests/module_factory.py index b9a4ed9127..ceb90539fc 100644 --- a/tests/module_factory.py +++ b/tests/module_factory.py @@ -561,9 +561,7 @@ def create_profiler_worker_obj(self, mock_db): ppid=Mock(), bloom_filters_manager=Mock(), name="mock_name", - localnet_cache={}, profiler_queue=Mock(), - handle_setting_local_net_lock=Mock(), input_handler=Mock(), aid_queue=Mock(), aid_manager=Mock(), @@ -860,6 +858,61 @@ def create_evidence_handler_obj(self, mock_db): handler.db = mock_db return handler + @patch(MODULE_DB_MANAGER, name="mock_db") + def create_evidence_handler_worker_obj(self, mock_db): + from slips_files.core.evidence_handler_worker import ( + EvidenceHandlerWorker, + ) + + def fake_read_configuration(worker): + worker.width = 3600 + worker.detection_threshold = 0.25 + worker.popup_alerts = False + worker.use_p2p = False + worker.exporting_modules_enabled = False + worker.generate_performance_plots = False + + with ( + patch( + "slips_files.core.evidence_handler_worker.Whitelist", + return_value=Mock(), + ), + patch( + "slips_files.core.evidence_handler_worker.IDMEFv2", + return_value=Mock(), + ), + patch( + "slips_files.core.evidence_handler_worker.Notify", + return_value=Mock(bin_found=False), + ), + patch( + "slips_files.core.evidence_handler_worker." + "EvidenceHandlerWorker.read_configuration", + new=fake_read_configuration, + ), + patch( + "slips_files.core.evidence_handler_worker.utils.get_own_ips", + return_value=[], + ), + ): + worker = EvidenceHandlerWorker( + logger=self.logger, + output_dir="/tmp", + redis_port=6379, + termination_event=Mock(), + slips_args=Mock(), + conf=Mock(), + ppid=Mock(), + bloom_filters_manager=Mock(), + name="EvidenceHandlerWorker_Process_0", + evidence_queue=Mock(), + evidence_logger_q=Mock(), + ) + + worker.db = mock_db + worker.print = Mock() + return worker + def create_evidence_loggr_obj(self): from slips_files.core.evidence_logger import EvidenceLogger @@ -1008,6 +1061,7 @@ def create_process_manager_obj(self): "fidesModule", "irisModule", ] + main_mock.conf.generate_performance_plots.return_value = False main_mock.input_type = InputType.PCAP main_mock.mode = "normal" main_mock.stdout = "" diff --git a/tests/unit/slips_files/core/database/redis_db/test_profile_handler.py b/tests/unit/slips_files/core/database/redis_db/test_profile_handler.py index 16c39c741b..553ad64897 100644 --- a/tests/unit/slips_files/core/database/redis_db/test_profile_handler.py +++ b/tests/unit/slips_files/core/database/redis_db/test_profile_handler.py @@ -517,7 +517,7 @@ def test_get_modified_tw_since_time( modified_tws = handler._get_modified_tw_since_time(time) handler.r.zrangebyscore.assert_called_once_with( - "ModifiedTW", time, float("+inf"), withscores=True + "modified_timewindows", time, float("+inf"), withscores=True ) assert modified_tws == expected_modified_tws @@ -1812,54 +1812,90 @@ def test_is_blocked_profile_and_tw(profile_tws, twid, expected_result): @pytest.mark.parametrize( - "timestamp, expected_zadd_call", + "timestamp, expected_zadd_calls", [ # Testcase 1: Normal timestamp ( 1000.0, - call("ModifiedTW", {"profile_1_timewindow1": 1000.0}), + [ + call( + "modified_timewindows", + {"profile_1_timewindow1": 1000.0}, + gt=True, + ), + call( + "modified_timewindows", + {"profile_1_timewindow1": 1000.0}, + nx=True, + ), + ], ), # Testcase 2: Timestamp as string ( "1000.0", - call("ModifiedTW", {"profile_1_timewindow1": 1000.0}), + [ + call( + "modified_timewindows", + {"profile_1_timewindow1": "1000.0"}, + gt=True, + ), + call( + "modified_timewindows", + {"profile_1_timewindow1": "1000.0"}, + nx=True, + ), + ], ), ], ) -def test_mark_profile_tw_as_modified(timestamp, expected_zadd_call): +def test_mark_profile_tw_as_modified(timestamp, expected_zadd_calls): handler = ModuleFactory().create_profile_handler_obj() handler.publish = MagicMock() handler.check_tw_to_close = MagicMock() + pipe = Mock() + handler.r.pipeline = Mock(return_value=pipe) profileid = "profile_1" twid = "timewindow1" + modified_tw_details = {f"{profileid}_{twid}": timestamp} with patch("time.time", return_value=1000.0): - handler.mark_profile_tw_as_modified(profileid, twid, timestamp) + handler.mark_profile_tw_as_modified(modified_tw_details) - handler.r.zadd.assert_called_once_with(*expected_zadd_call.args) - handler.publish.assert_called_once_with( - "tw_modified", - json.dumps( - { - "profileid": profileid, - "twid": twid, - } - ), - ) + handler.r.pipeline.assert_called_once_with() + pipe.zadd.assert_has_calls(expected_zadd_calls) + pipe.execute.assert_called_once_with() -def test_mark_profile_tw_as_modified_requires_timestamp(): +def test_mark_profile_tw_as_modified_allows_missing_timestamp(): handler = ModuleFactory().create_profile_handler_obj() handler.publish = MagicMock() handler.check_tw_to_close = MagicMock() + pipe = Mock() + handler.r.pipeline = Mock(return_value=pipe) profileid = "profile_1" twid = "timewindow1" - with pytest.raises(ValueError): - handler.mark_profile_tw_as_modified(profileid, twid, None) + modified_tw_details = {f"{profileid}_{twid}": None} - handler.r.zadd.assert_not_called() + handler.mark_profile_tw_as_modified(modified_tw_details) + + handler.r.pipeline.assert_called_once_with() + pipe.zadd.assert_has_calls( + [ + call( + "modified_timewindows", + {"profile_1_timewindow1": None}, + gt=True, + ), + call( + "modified_timewindows", + {"profile_1_timewindow1": None}, + nx=True, + ), + ] + ) + pipe.execute.assert_called_once_with() handler.publish.assert_not_called() diff --git a/tests/unit/slips_files/core/database/test_database.py b/tests/unit/slips_files/core/database/test_database.py index 0e5790dc8c..5534d17219 100644 --- a/tests/unit/slips_files/core/database/test_database.py +++ b/tests/unit/slips_files/core/database/test_database.py @@ -55,7 +55,7 @@ def test_subscribe(): # invalid channel assert db.subscribe("invalid_channel") is False # valid channel, shoud return a pubsub object - assert isinstance(db.subscribe("tw_modified"), redis.client.PubSub) + assert isinstance(db.subscribe("new_flow"), redis.client.PubSub) def test_profile_moddule_labels(): diff --git a/tests/unit/slips_files/core/helpers/test_localnet_handler.py b/tests/unit/slips_files/core/helpers/test_localnet_handler.py new file mode 100644 index 0000000000..537bad69e0 --- /dev/null +++ b/tests/unit/slips_files/core/helpers/test_localnet_handler.py @@ -0,0 +1,187 @@ +import ipaddress +from unittest.mock import MagicMock, Mock, call, patch + +import netifaces +import pytest + +from slips_files.core.helpers.localnet_handler import LocalnetHandler + + +def create_profiler( + *, client_ips=None, running_non_stop=False, localnet_cache=None +): + profiler = Mock() + profiler.client_ips = client_ips or [] + profiler.args = Mock(interface=None, access_point=None) + profiler.db = Mock() + profiler.db.is_running_non_stop.return_value = running_non_stop + profiler.handle_setting_local_net_lock = MagicMock() + profiler.is_ignored_ip.return_value = False + return profiler + + +def test_get_private_client_ips_filters_private_entries(): + profiler = create_profiler() + handler = LocalnetHandler(profiler) + + private_clients = handler.get_private_client_ips( + [ + "192.168.1.2", + "8.8.8.8", + ipaddress.IPv4Network("10.0.0.0/8"), + ] + ) + + assert private_clients == [ + "192.168.1.2", + ipaddress.IPv4Network("10.0.0.0/8"), + ] + + +def test_get_private_client_ips_returns_empty_list_for_non_iterable(): + profiler = create_profiler() + handler = LocalnetHandler(profiler) + + assert handler.get_private_client_ips(1) == [] + + +def test_get_local_net_of_flow_prefers_configured_default_localnet(): + profiler = create_profiler( + client_ips=[ipaddress.IPv4Network("192.168.1.0/24")] + ) + handler = LocalnetHandler(profiler) + flow = Mock(saddr="10.0.0.8") + + localnet = handler._get_local_net_of_flow(flow) + + assert localnet == {"default": "192.168.1.0/24"} + + +@patch("slips_files.core.helpers.localnet_handler.netifaces.ifaddresses") +@patch("slips_files.core.helpers.localnet_handler.utils.get_all_interfaces") +def test_get_localnet_of_given_interface_returns_ipv4_networks( + mock_get_all_interfaces, mock_ifaddresses +): + profiler = create_profiler(running_non_stop=True) + handler = LocalnetHandler(profiler) + mock_get_all_interfaces.return_value = ["eth0", "wlan0"] + mock_ifaddresses.side_effect = [ + { + netifaces.AF_INET: [ + {"addr": "192.168.1.12", "netmask": "255.255.255.0"} + ] + }, + {netifaces.AF_INET: [{"addr": "10.0.0.25", "netmask": "255.0.0.0"}]}, + ] + + localnets = handler._get_localnet_of_given_interfaces_using_netifaces() + + assert localnets == { + "eth0": "192.168.1.0/24", + "wlan0": "10.0.0.0/8", + } + + +def test_handle_setting_local_net_updates_cache_and_db(): + profiler = create_profiler(running_non_stop=False) + handler = LocalnetHandler(profiler) + handler.localnet_cache = {"old": "127.0.0.0/8"} + handler._should_set_localnet = Mock(return_value=True) + handler._get_local_net_of_flow = Mock( + return_value={"default": "192.168.1.0/24"} + ) + flow = Mock(saddr="192.168.1.8", interface="eth0") + + handler.handle_setting_local_net(flow) + + assert handler.localnet_cache == {"default": "192.168.1.0/24"} + profiler.db.set_local_network.assert_called_once_with( + "192.168.1.0/24", "default" + ) + + +@pytest.mark.parametrize( + "running_non_stop, localnet_cache, client_ips, saddr, interface, " + "is_ignored_ip, expected", + [ + ( + False, + {"default": "192.168.1.0/24"}, + [], + "192.168.1.8", + "eth0", + False, + False, + ), + ( + True, + {"eth0": "192.168.1.0/24"}, + [], + "192.168.1.8", + "eth0", + False, + False, + ), + (False, {}, [], "0.0.0.0", "eth0", False, False), + ( + False, + {}, + [ipaddress.IPv4Network("10.0.0.0/8")], + "8.8.8.8", + "eth0", + False, + True, + ), + (False, {}, [], "not-an-ip", "eth0", False, False), + (False, {}, [], "224.0.0.1", "eth0", True, False), + (False, {}, [], "8.8.8.8", "eth0", False, False), + (False, {}, [], "192.168.1.8", "eth0", False, True), + ], +) +def test_should_set_localnet( + running_non_stop, + localnet_cache, + client_ips, + saddr, + interface, + is_ignored_ip, + expected, +): + profiler = create_profiler( + client_ips=client_ips, + running_non_stop=running_non_stop, + localnet_cache=localnet_cache, + ) + profiler.is_ignored_ip.return_value = is_ignored_ip + handler = LocalnetHandler(profiler) + handler.localnet_cache = localnet_cache + flow = Mock(saddr=saddr, interface=interface) + + assert handler._should_set_localnet(flow) is expected + + +def test_handle_setting_local_net_stores_interface_localnets_in_non_stop_mode(): + profiler = create_profiler(running_non_stop=True) + handler = LocalnetHandler(profiler) + handler._should_set_localnet = Mock(return_value=True) + handler._get_localnet_of_given_interfaces_using_netifaces = Mock( + return_value={ + "eth0": "192.168.1.0/24", + "wlan0": "10.0.0.0/8", + } + ) + flow = Mock(saddr="192.168.1.8", interface="eth0") + + handler.handle_setting_local_net(flow) + + assert handler.localnet_cache == { + "eth0": "192.168.1.0/24", + "wlan0": "10.0.0.0/8", + } + profiler.db.set_local_network.assert_has_calls( + [ + call("192.168.1.0/24", "eth0"), + call("10.0.0.0/8", "wlan0"), + ], + any_order=False, + ) diff --git a/tests/unit/slips_files/core/input/test_input.py b/tests/unit/slips_files/core/input/test_input.py index 3c9ddb5003..c89ba7eac1 100644 --- a/tests/unit/slips_files/core/input/test_input.py +++ b/tests/unit/slips_files/core/input/test_input.py @@ -309,6 +309,24 @@ def test_read_from_stdin(line_type: str, line: str): assert line_sent["input_type"] == InputType.STDIN +def test_give_profiler_skips_flow_per_minute_when_disabled(): + input = ModuleFactory().create_input_obj("", InputType.STDIN) + input.conf.generate_performance_plots.return_value = False + + input.give_profiler({"line": "value"}) + + input.db.record_flow_per_minute.assert_not_called() + + +def test_give_profiler_records_flow_per_minute_when_enabled(): + input = ModuleFactory().create_input_obj("", InputType.STDIN) + input.conf.generate_performance_plots.return_value = True + + input.give_profiler({"line": "value"}) + + input.db.record_flow_per_minute.assert_called_once_with("input") + + @pytest.mark.parametrize( "line, input_type, expected_line, expected_input_type", [ diff --git a/tests/unit/slips_files/core/test_evidence_handler.py b/tests/unit/slips_files/core/test_evidence_handler.py index 0feaad7f3b..e889a16130 100644 --- a/tests/unit/slips_files/core/test_evidence_handler.py +++ b/tests/unit/slips_files/core/test_evidence_handler.py @@ -1,471 +1,152 @@ # SPDX-FileCopyrightText: 2021 Sebastian Garcia # SPDX-License-Identifier: GPL-2.0-only -from multiprocessing import Event - -import pytest -from unittest.mock import Mock, MagicMock, patch - -from slips_files.core.structures.alerts import Alert -from slips_files.core.structures.evidence import ( - Evidence, - ProfileID, - EvidenceType, - TimeWindow, - Attacker, - IoCType, - Direction, - ThreatLevel, -) + +from unittest.mock import Mock, call, patch + +from slips_files.core.evidence_handler import DEFAULT_EVIDENCE_HANDLER_WORKERS from tests.module_factory import ModuleFactory -from datetime import datetime - - -@pytest.mark.parametrize( - "profileid, our_ips, expected_result, expected_publish_call_count", - [ - # testcase1: IP not in our_ips, should block - ("192.168.1.100", ["10.0.0.1", "172.16.0.1"], True, 1), - # testcase2: IP in our_ips, should not block - ("10.0.0.1", ["10.0.0.1", "172.16.0.1"], False, 0), - # testcase3: Empty our_ips, should block - ("8.8.8.8", [], True, 1), - ], -) -def test_decide_blocking( - mocker, profileid, our_ips, expected_result, expected_publish_call_count -): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.blocking_modules_supported = True - evidence_handler.our_ips = our_ips - with patch.object(evidence_handler.db, "publish") as mock_publish: - tw = TimeWindow( - 2, "2025-05-09T13:27:45.123456", "2025-05-09T13:27:45.123456" - ) - mocker.patch( - "slips_files.common.slips_utils.Utils.get_interface_of_ip", - return_value="eth0", - ) - result = evidence_handler.decide_blocking(profileid, tw) - - assert result == expected_result - assert mock_publish.call_count == expected_publish_call_count def test_shutdown_gracefully(): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.logger_thread = Mock() - evidence_handler.logger_stop_signal = Event() - - evidence_handler.shutdown_gracefully() - - assert evidence_handler.logger_stop_signal.is_set() - evidence_handler.logger_thread.join.assert_called_once_with(timeout=5) - - -@pytest.mark.parametrize( - "profileid, twid, past_alerts, expected_output", - [ - # testcase1: No past alerts - ("profile1_192.168.1.1", "timewindow1", {}, []), - # testcase2: One past alert - ( - "profile2_10.0.0.1", - "timewindow2", - {"alert1": '["evidence1", "evidence2"]'}, - ["evidence1", "evidence2"], - ), - ], -) -def test_get_evidence_that_were_part_of_a_past_alert( - profileid, twid, past_alerts, expected_output -): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.db.get_profileid_twid_alerts.return_value = past_alerts - - result = evidence_handler.get_evidence_that_were_part_of_a_past_alert( - profileid, twid - ) - assert result == expected_output + handler = ModuleFactory().create_evidence_handler_obj() + handler.stop_evidence_workers = Mock() + handler.logger_stop_signal = Mock() + handler.logger_thread = Mock() + handler.evidence_worker_queue = Mock() + handler.evidence_logger_q = Mock() + handler.shutdown_gracefully() -def setup_handler(popup_enabled, blocked, mark_blocked=None): + handler.stop_evidence_workers.assert_called_once() + handler.logger_stop_signal.set.assert_called_once() + handler.logger_thread.join.assert_called_once_with(timeout=5) + handler.evidence_worker_queue.cancel_join_thread.assert_called_once() + handler.evidence_worker_queue.close.assert_called_once() + handler.evidence_logger_q.cancel_join_thread.assert_called_once() + handler.evidence_logger_q.close.assert_called_once() + + +def test_stop_evidence_workers(): handler = ModuleFactory().create_evidence_handler_obj() - handler.popup_alerts = popup_enabled - - alert = Alert( - profile=ProfileID("1.2.3.4"), - timewindow=TimeWindow(1), - last_evidence=Mock(), - accumulated_threat_level=12.2, - last_flow_datetime="2024/10/04 15:45:30.123456+0000", - ) - evidence = {"k": MagicMock(spec=Evidence)} - - handler.db.set_alert = MagicMock() - handler.decide_blocking = MagicMock(side_effect=[False, mark_blocked]) - handler.db.is_blocked_profile_and_tw = MagicMock(return_value=blocked) - handler.send_to_exporting_module = MagicMock() - handler.formatter.format_evidence_for_printing = MagicMock( - return_value="formatted_alert" - ) - handler.print = MagicMock() - handler.show_popup = MagicMock() - handler.db.mark_profile_and_timewindow_as_blocked = MagicMock() - handler.log_alert = MagicMock() - - return handler, alert, evidence - - -@pytest.mark.parametrize("popup_enabled", [True, False]) -def test_handle_new_alert_already_blocked(popup_enabled): - handler, alert, evidence = setup_handler(popup_enabled, blocked=True) - handler.handle_new_alert(alert, evidence) - - handler.db.set_alert.assert_called_once_with(alert, evidence) - handler.db.is_blocked_profile_and_tw.assert_called_once() - handler.send_to_exporting_module.assert_not_called() - handler.print.assert_not_called() - handler.show_popup.assert_not_called() - handler.db.mark_profile_and_timewindow_as_blocked.assert_not_called() - handler.log_alert.assert_not_called() - - -@pytest.mark.parametrize( - "popup_enabled, expect_popup", - [ - (True, True), - (False, False), - ], -) -def test_handle_new_alert_not_blocked(popup_enabled, expect_popup): - handler, alert, evidence = setup_handler( - popup_enabled, blocked=False, mark_blocked=True + process_1 = Mock() + process_2 = Mock() + handler.evidence_worker_child_processes = [process_1, process_2] + handler.evidence_worker_queue = Mock() + + handler.stop_evidence_workers() + + assert handler.evidence_worker_queue.put.call_args_list == [ + call("stop"), + call("stop"), + ] + process_1.join.assert_called_once() + process_2.join.assert_called_once() + + +@patch("slips_files.core.evidence_handler.EvidenceHandlerWorker") +def test_start_evidence_worker(mock_worker_cls): + handler = ModuleFactory().create_evidence_handler_obj() + worker = mock_worker_cls.return_value + handler.evidence_worker_child_processes = [] + handler.evidence_worker_queue = Mock() + handler.evidence_logger_q = Mock() + + handler.start_evidence_worker(7) + + mock_worker_cls.assert_called_once_with( + logger=handler.logger, + output_dir=handler.output_dir, + redis_port=handler.redis_port, + termination_event=handler.termination_event, + conf=handler.conf, + ppid=handler.ppid, + slips_args=handler.args, + bloom_filters_manager=handler.bloom_filters, + name="EvidenceHandlerWorker_Process_7", + evidence_queue=handler.evidence_worker_queue, + evidence_logger_q=handler.evidence_logger_q, ) - handler.handle_new_alert(alert, evidence) + worker.start.assert_called_once() + assert handler.evidence_worker_child_processes == [worker] - handler.send_to_exporting_module.assert_called_once_with(evidence) - handler.print.assert_called_once_with("formatted_alert", 1, 0) - if expect_popup: - handler.show_popup.assert_called_once_with(alert) - else: - handler.show_popup.assert_not_called() +def test_should_stop_returns_false_if_termination_not_set(): + handler = ModuleFactory().create_evidence_handler_obj() + handler.termination_event.is_set.return_value = False - handler.db.mark_profile_and_timewindow_as_blocked.assert_not_called() - handler.log_alert.assert_called_once_with(alert, blocked=False) + assert handler.should_stop() is False -@pytest.mark.parametrize( - "data", - [ - "Test log entry", - "Another log entry", - ], -) -def test_add_to_log_file(data): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.evidence_logger_q.put = Mock() +@patch("slips_files.core.evidence_handler.time.time", return_value=100.0) +def test_should_stop_waits_when_messages_are_still_arriving(_mock_time): + handler = ModuleFactory().create_evidence_handler_obj() + handler.termination_event.is_set.return_value = True + handler.is_msg_received_in_any_channel = Mock(return_value=True) + handler.last_msg_received_time = 10.0 - # Act - evidence_handler.add_to_log_file(data) + assert handler.should_stop() is False + assert handler.last_msg_received_time == 100.0 - # Assert - evidence_handler.evidence_logger_q.put.assert_called_once_with( - {"to_log": data, "where": "alerts.log"} - ) +@patch("slips_files.core.evidence_handler.time.time", return_value=120.0) +def test_should_stop_waits_for_grace_period(_mock_time): + handler = ModuleFactory().create_evidence_handler_obj() + handler.termination_event.is_set.return_value = True + handler.is_msg_received_in_any_channel = Mock(return_value=False) + handler.last_msg_received_time = 100.0 -@pytest.mark.parametrize( - "all_uids, timewindow, accumulated_threat_level", - [ # Testcase1: Basic alert with UIDs and threat level - ( - ["uid1", "uid2"], - 1, - 0.5, - ), - # Testcase2: Alert without UIDs, high threat level - ( - [], - 10, - 1.0, - ), - ], -) -def test_add_alert_to_json_log_file( - all_uids, timewindow, accumulated_threat_level -): - mock_file = Mock() - alert = Alert( - profile=ProfileID("192.168.1.20"), - timewindow=TimeWindow( - timewindow, - start_time="2024-10-04T18:46:50+03:00", - end_time="2024-10-04T19:46:50+03:00", - ), - last_evidence=Evidence( - evidence_type=EvidenceType.ARP_SCAN, - description="ARP scan detected", - attacker=Attacker( - direction=Direction.SRC, - ioc_type=IoCType.IP, - value="192.168.1.20", - ), - threat_level=ThreatLevel.INFO, - profile=ProfileID("192.168.1.20"), - timewindow=TimeWindow(timewindow), - uid=all_uids, - timestamp="1728417813.8868346", - ), - accumulated_threat_level=accumulated_threat_level, - last_flow_datetime="2024/10/04 15:45:30.123456+0000", - ) - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.jsonfile = mock_file - evidence_handler.idmefv2.convert_to_idmef_alert = Mock( - return_value="alert_in_idmef_format" - ) - evidence_handler.evidence_logger_q.put = Mock() - - evidence_handler.add_alert_to_json_log_file(alert) - evidence_handler.evidence_logger_q.put.assert_called_once_with( - { - "to_log": "alert_in_idmef_format", - "where": "alerts.json", - } - ) + assert handler.should_stop() is False -def test_show_popup(): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.notify = Mock() - alert = Mock(spec=Alert) - evidence_handler.formatter.get_printable_alert = Mock( - return_value="alert_time_desc" - ) +@patch("slips_files.core.evidence_handler.time.time", return_value=131.0) +def test_should_stop_after_grace_period(_mock_time): + handler = ModuleFactory().create_evidence_handler_obj() + handler.termination_event.is_set.return_value = True + handler.is_msg_received_in_any_channel = Mock(return_value=False) + handler.last_msg_received_time = 100.0 - evidence_handler.show_popup(alert) + assert handler.should_stop() is True - evidence_handler.notify.show_popup.assert_called_once_with( - "alert_time_desc" - ) +def test_pre_main_starts_default_workers(): + handler = ModuleFactory().create_evidence_handler_obj() + handler.start_evidence_worker = Mock() -def test_send_to_exporting_module(): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - tw_evidence = { - "evidence1": Evidence( - evidence_type=EvidenceType.ARP_SCAN, - description="ARP scan detected", - attacker=Attacker( - direction=Direction.SRC, - ioc_type=IoCType.IP, - value="192.168.1.1", - ), - threat_level=ThreatLevel.MEDIUM, - profile=ProfileID(ip="192.168.1.1"), - timewindow=TimeWindow(number=1), - uid=["uid1"], - timestamp="2023/04/01 10:00:00.000000+0000", - ), - "evidence2": Evidence( - evidence_type=EvidenceType.DNS_WITHOUT_CONNECTION, - description="DNS query without connection", - attacker=Attacker( - direction=Direction.SRC, - ioc_type=IoCType.IP, - value="192.168.1.2", - ), - threat_level=ThreatLevel.LOW, - profile=ProfileID(ip="192.168.1.2"), - timewindow=TimeWindow(number=1), - uid=["uid2"], - timestamp="2023/04/01 10:01:00.000000+0000", - ), - } - - evidence_handler.db.publish = Mock() - evidence_handler.send_to_exporting_module(tw_evidence) - assert evidence_handler.db.publish.call_count == 2 - - -@pytest.mark.parametrize( - "sys_argv, running_non_stop, expected_result", - [ - # testcase 1: running non stop with -p enabled - (["-i", "-p"], True, True), - # testcase 2: custom flows but the module is disabled - (["-i", "-im"], False, False), - # testcase 3: -i not in sys.argv and not running non stop - ([], False, False), - ], -) -def test_is_blocking_module_supported( - sys_argv, running_non_stop, expected_result -): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.is_running_non_stop = running_non_stop - - with patch("sys.argv", sys_argv): - result = evidence_handler.is_blocking_modules_supported() - assert result == expected_result - - -@pytest.mark.parametrize( - "evidence, past_evidence_ids, expected_result", - [ - # testcase1: Evidence not filtered - ( - Evidence( - evidence_type=EvidenceType.ARP_SCAN, - description="", - attacker=Attacker( - direction="SRC", - ioc_type=IoCType.IP, - value="192.168.1.1", - ), - threat_level=ThreatLevel.INFO, - profile=ProfileID("192.168.1.1"), - timewindow=TimeWindow(1), - uid=[], - timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), - id="1", - ), - [], - False, - ), - # testcase2: Evidence filtered (part of past alert) - ( - Evidence( - evidence_type=EvidenceType.ARP_SCAN, - description="", - attacker=Attacker( - direction="SRC", - ioc_type=IoCType.IP, - value="192.168.1.1", - ), - threat_level=ThreatLevel.INFO, - profile=ProfileID("192.168.1.1"), - timewindow=TimeWindow(1), - uid=[], - timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), - id="2", - ), - ["2"], - True, - ), - # testcase3: Evidence filtered (evidence that wasnt done by the given - # profileid) - ( - Evidence( - evidence_type=EvidenceType.ARP_SCAN, - description="", - attacker=Attacker( - direction="DST", - ioc_type=IoCType.IP, - value="192.168.1.1", - ), - threat_level=ThreatLevel.INFO, - profile=ProfileID("192.168.1.1"), - timewindow=TimeWindow(1), - uid=[], - timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), - id="3", - ), - [], - True, - ), - ], -) -def test_is_filtered_evidence(evidence, past_evidence_ids, expected_result): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - result = evidence_handler.is_filtered_evidence(evidence, past_evidence_ids) - assert result == expected_result - - -@pytest.mark.parametrize( - "evidence, expected_result", - [ # Testcase1: Attacker direction is SRC - (Mock(attacker=Mock(direction="SRC")), False), - # Testcase2: Attacker direction is DST - (Mock(attacker=Mock(direction="DST")), True), - ], -) -def test_is_evidence_done_by_others(evidence, expected_result): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - result = evidence_handler.is_evidence_done_by_others(evidence) - assert result == expected_result - - -@pytest.mark.parametrize( - "confidence, threat_level, expected_output", - [ - # Testcase 1: Low threat level, confidence 0.5 - (0.5, ThreatLevel.LOW, 0.1), - # Testcase 2: Medium threat level, full confidence - (1.0, ThreatLevel.MEDIUM, 0.5), - # Testcase 3: High threat level, confidence 0.8 - (0.8, ThreatLevel.HIGH, 0.64), - # Testcase 4: Critical threat level, confidence 0.3 - (0.3, ThreatLevel.CRITICAL, 0.3), - # Testcase 5: Info threat level, zero confidence - (0.0, ThreatLevel.INFO, 0.0), - ], -) -def test_get_threat_level(confidence, threat_level, expected_output): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence = Mock(spec=Evidence) - evidence.confidence = confidence - evidence.threat_level = threat_level - with patch.object(evidence_handler, "print") as mock_print: - result = evidence_handler.get_threat_level(evidence) - - assert pytest.approx(result, abs=1e-6) == expected_output - mock_print.assert_called_once_with( - f"\t\tWeighted Threat Level: {result}", 3, 0 + handler.pre_main() + + assert handler.start_evidence_worker.call_count == ( + DEFAULT_EVIDENCE_HANDLER_WORKERS ) + handler.start_evidence_worker.assert_has_calls([call(0), call(1), call(2)]) -@pytest.mark.parametrize( - "ip, twid, flow_datetime, " "accumulated_threat_level, blocked", - [ - # testcase1: IP blocked by blocking module - ( - "192.168.1.100", - 1, - "2023/10/26 10:10:10", - 0.8, - True, +def test_main_queues_received_messages(): + handler = ModuleFactory().create_evidence_handler_obj() + handler.should_stop = Mock(side_effect=[False, True]) + handler.evidence_worker_queue = Mock() + + def get_msg(channel): + if channel == "evidence_added": + return {"data": "evidence"} + if channel == "new_blame": + return {"data": "blame"} + return None + + handler.get_msg = Mock(side_effect=get_msg) + + handler.main() + + assert handler.evidence_worker_queue.put.call_args_list == [ + call( + { + "channel": "evidence_added", + "message": {"data": "evidence"}, + } ), - # testcase2: IP not blocked by blocking module - ( - "10.0.0.100", - 2, - "2023/10/26 11:11:11", - 1.0, - False, + call( + { + "channel": "new_blame", + "message": {"data": "blame"}, + } ), - ], -) -def test_log_alert( - ip, - twid, - flow_datetime, - accumulated_threat_level, - blocked, -): - evidence_handler = ModuleFactory().create_evidence_handler_obj() - evidence_handler.width = 300 - evidence_handler.add_alert_to_json_log_file = Mock() - evidence_handler.add_to_log_file = Mock() - alert = Alert( - profile=ProfileID(ip), - timewindow=TimeWindow(twid), - last_evidence=Mock(), - accumulated_threat_level=accumulated_threat_level, - last_flow_datetime=flow_datetime, - ) - evidence_handler.log_alert(alert, blocked=blocked) - - evidence_handler.add_alert_to_json_log_file.assert_called_once() - assert flow_datetime in evidence_handler.add_to_log_file.call_args[0][0] - assert str(twid) in evidence_handler.add_to_log_file.call_args[0][0] + ] diff --git a/tests/unit/slips_files/core/test_evidence_handler_worker.py b/tests/unit/slips_files/core/test_evidence_handler_worker.py new file mode 100644 index 0000000000..4ad9a1fe4d --- /dev/null +++ b/tests/unit/slips_files/core/test_evidence_handler_worker.py @@ -0,0 +1,416 @@ +# SPDX-FileCopyrightText: 2021 Sebastian Garcia +# SPDX-License-Identifier: GPL-2.0-only +from datetime import datetime +from unittest.mock import MagicMock, Mock, patch + +import pytest + +from slips_files.core.structures.alerts import Alert +from slips_files.core.structures.evidence import ( + Attacker, + Direction, + Evidence, + EvidenceType, + IoCType, + ProfileID, + ThreatLevel, + TimeWindow, +) +from tests.module_factory import ModuleFactory + + +@pytest.mark.parametrize( + "profileid, our_ips, expected_result, expected_publish_call_count", + [ + ("192.168.1.100", ["10.0.0.1", "172.16.0.1"], True, 1), + ("10.0.0.1", ["10.0.0.1", "172.16.0.1"], False, 0), + ("8.8.8.8", [], True, 1), + ], +) +def test_decide_blocking( + mocker, profileid, our_ips, expected_result, expected_publish_call_count +): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.blocking_modules_supported = True + worker.our_ips = our_ips + with patch.object(worker.db, "publish") as mock_publish: + tw = TimeWindow( + 2, "2025-05-09T13:27:45.123456", "2025-05-09T13:27:45.123456" + ) + mocker.patch( + "slips_files.common.slips_utils.Utils.get_interface_of_ip", + return_value="eth0", + ) + + result = worker.decide_blocking(profileid, tw) + + assert result == expected_result + assert mock_publish.call_count == expected_publish_call_count + + +@pytest.mark.parametrize( + "profileid, twid, past_alerts, expected_output", + [ + ("profile1_192.168.1.1", "timewindow1", {}, []), + ( + "profile2_10.0.0.1", + "timewindow2", + {"alert1": '["evidence1", "evidence2"]'}, + ["evidence1", "evidence2"], + ), + ], +) +def test_get_evidence_that_were_part_of_a_past_alert( + profileid, twid, past_alerts, expected_output +): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.db.get_profileid_twid_alerts.return_value = past_alerts + + result = worker.get_evidence_that_were_part_of_a_past_alert( + profileid, twid + ) + + assert result == expected_output + + +def setup_worker(popup_enabled, blocked, mark_blocked=None): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.popup_alerts = popup_enabled + + alert = Alert( + profile=ProfileID("1.2.3.4"), + timewindow=TimeWindow(1), + last_evidence=Mock(), + accumulated_threat_level=12.2, + last_flow_datetime="2024/10/04 15:45:30.123456+0000", + ) + evidence = {"k": MagicMock(spec=Evidence)} + + worker.db.set_alert = MagicMock() + worker.decide_blocking = MagicMock(side_effect=[False, mark_blocked]) + worker.db.is_blocked_profile_and_tw = MagicMock(return_value=blocked) + worker.send_to_exporting_module = MagicMock() + worker.formatter.format_evidence_for_printing = MagicMock( + return_value="formatted_alert" + ) + worker.print = MagicMock() + worker.show_popup = MagicMock() + worker.db.mark_profile_and_timewindow_as_blocked = MagicMock() + worker.log_alert = MagicMock() + + return worker, alert, evidence + + +@pytest.mark.parametrize("popup_enabled", [True, False]) +def test_handle_new_alert_already_blocked(popup_enabled): + worker, alert, evidence = setup_worker(popup_enabled, blocked=True) + + worker.handle_new_alert(alert, evidence) + + worker.db.set_alert.assert_called_once_with(alert, evidence) + worker.db.is_blocked_profile_and_tw.assert_called_once() + worker.send_to_exporting_module.assert_not_called() + worker.print.assert_not_called() + worker.show_popup.assert_not_called() + worker.db.mark_profile_and_timewindow_as_blocked.assert_not_called() + worker.log_alert.assert_not_called() + + +@pytest.mark.parametrize( + "popup_enabled, expect_popup", + [ + (True, True), + (False, False), + ], +) +def test_handle_new_alert_not_blocked(popup_enabled, expect_popup): + worker, alert, evidence = setup_worker( + popup_enabled, blocked=False, mark_blocked=True + ) + + worker.handle_new_alert(alert, evidence) + + worker.send_to_exporting_module.assert_called_once_with(evidence) + worker.print.assert_called_once_with("formatted_alert", 1, 0) + if expect_popup: + worker.show_popup.assert_called_once_with(alert) + else: + worker.show_popup.assert_not_called() + worker.db.mark_profile_and_timewindow_as_blocked.assert_not_called() + worker.log_alert.assert_called_once_with(alert, blocked=False) + + +@pytest.mark.parametrize("data", ["Test log entry", "Another log entry"]) +def test_add_to_log_file(data): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.evidence_logger_q.put = Mock() + + worker.add_to_log_file(data) + + worker.evidence_logger_q.put.assert_called_once_with( + {"to_log": data, "where": "alerts.log"} + ) + + +@pytest.mark.parametrize( + "all_uids, timewindow, accumulated_threat_level", + [ + (["uid1", "uid2"], 1, 0.5), + ([], 10, 1.0), + ], +) +def test_add_alert_to_json_log_file( + all_uids, timewindow, accumulated_threat_level +): + alert = Alert( + profile=ProfileID("192.168.1.20"), + timewindow=TimeWindow( + timewindow, + start_time="2024-10-04T18:46:50+03:00", + end_time="2024-10-04T19:46:50+03:00", + ), + last_evidence=Evidence( + evidence_type=EvidenceType.ARP_SCAN, + description="ARP scan detected", + attacker=Attacker( + direction=Direction.SRC, + ioc_type=IoCType.IP, + value="192.168.1.20", + ), + threat_level=ThreatLevel.INFO, + profile=ProfileID("192.168.1.20"), + timewindow=TimeWindow(timewindow), + uid=all_uids, + timestamp="1728417813.8868346", + ), + accumulated_threat_level=accumulated_threat_level, + last_flow_datetime="2024/10/04 15:45:30.123456+0000", + ) + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.idmefv2.convert_to_idmef_alert = Mock( + return_value="alert_in_idmef_format" + ) + worker.evidence_logger_q.put = Mock() + + worker.add_alert_to_json_log_file(alert) + + worker.evidence_logger_q.put.assert_called_once_with( + { + "to_log": "alert_in_idmef_format", + "where": "alerts.json", + } + ) + + +def test_show_popup(): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.notify = Mock() + alert = Mock(spec=Alert) + worker.formatter.get_printable_alert = Mock(return_value="alert_time_desc") + + worker.show_popup(alert) + + worker.notify.show_popup.assert_called_once_with("alert_time_desc") + + +def test_send_to_exporting_module(): + worker = ModuleFactory().create_evidence_handler_worker_obj() + tw_evidence = { + "evidence1": Evidence( + evidence_type=EvidenceType.ARP_SCAN, + description="ARP scan detected", + attacker=Attacker( + direction=Direction.SRC, + ioc_type=IoCType.IP, + value="192.168.1.1", + ), + threat_level=ThreatLevel.MEDIUM, + profile=ProfileID(ip="192.168.1.1"), + timewindow=TimeWindow(number=1), + uid=["uid1"], + timestamp="2023/04/01 10:00:00.000000+0000", + ), + "evidence2": Evidence( + evidence_type=EvidenceType.DNS_WITHOUT_CONNECTION, + description="DNS query without connection", + attacker=Attacker( + direction=Direction.SRC, + ioc_type=IoCType.IP, + value="192.168.1.2", + ), + threat_level=ThreatLevel.LOW, + profile=ProfileID(ip="192.168.1.2"), + timewindow=TimeWindow(number=1), + uid=["uid2"], + timestamp="2023/04/01 10:01:00.000000+0000", + ), + } + + worker.exporting_modules_enabled = True + worker.db.publish = Mock() + + worker.send_to_exporting_module(tw_evidence) + + assert worker.db.publish.call_count == 2 + + +@pytest.mark.parametrize( + "sys_argv, running_non_stop, expected_result", + [ + (["-i", "-p"], True, True), + (["-i", "-im"], False, False), + ([], False, False), + ], +) +def test_is_blocking_module_supported( + sys_argv, running_non_stop, expected_result +): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.is_running_non_stop = running_non_stop + + with patch("sys.argv", sys_argv): + result = worker.is_blocking_modules_supported() + + assert result == expected_result + + +@pytest.mark.parametrize( + "evidence, past_evidence_ids, expected_result", + [ + ( + Evidence( + evidence_type=EvidenceType.ARP_SCAN, + description="", + attacker=Attacker( + direction="SRC", + ioc_type=IoCType.IP, + value="192.168.1.1", + ), + threat_level=ThreatLevel.INFO, + profile=ProfileID("192.168.1.1"), + timewindow=TimeWindow(1), + uid=[], + timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), + id="1", + ), + [], + False, + ), + ( + Evidence( + evidence_type=EvidenceType.ARP_SCAN, + description="", + attacker=Attacker( + direction="SRC", + ioc_type=IoCType.IP, + value="192.168.1.1", + ), + threat_level=ThreatLevel.INFO, + profile=ProfileID("192.168.1.1"), + timewindow=TimeWindow(1), + uid=[], + timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), + id="2", + ), + ["2"], + True, + ), + ( + Evidence( + evidence_type=EvidenceType.ARP_SCAN, + description="", + attacker=Attacker( + direction="DST", + ioc_type=IoCType.IP, + value="192.168.1.1", + ), + threat_level=ThreatLevel.INFO, + profile=ProfileID("192.168.1.1"), + timewindow=TimeWindow(1), + uid=[], + timestamp=datetime.now().strftime("%Y/%m/%d %H:%M:%S.%f%z"), + id="3", + ), + [], + True, + ), + ], +) +def test_is_filtered_evidence(evidence, past_evidence_ids, expected_result): + worker = ModuleFactory().create_evidence_handler_worker_obj() + + result = worker.is_filtered_evidence(evidence, past_evidence_ids) + + assert result == expected_result + + +@pytest.mark.parametrize( + "evidence, expected_result", + [ + (Mock(attacker=Mock(direction="SRC")), False), + (Mock(attacker=Mock(direction="DST")), True), + ], +) +def test_is_evidence_done_by_others(evidence, expected_result): + worker = ModuleFactory().create_evidence_handler_worker_obj() + + result = worker.is_evidence_done_by_others(evidence) + + assert result == expected_result + + +@pytest.mark.parametrize( + "confidence, threat_level, expected_output", + [ + (0.5, ThreatLevel.LOW, 0.1), + (1.0, ThreatLevel.MEDIUM, 0.5), + (0.8, ThreatLevel.HIGH, 0.64), + (0.3, ThreatLevel.CRITICAL, 0.3), + (0.0, ThreatLevel.INFO, 0.0), + ], +) +def test_get_threat_level(confidence, threat_level, expected_output): + worker = ModuleFactory().create_evidence_handler_worker_obj() + evidence = Mock(spec=Evidence) + evidence.confidence = confidence + evidence.threat_level = threat_level + + with patch.object(worker, "print") as mock_print: + result = worker.get_threat_level(evidence) + + assert pytest.approx(result, abs=1e-6) == expected_output + mock_print.assert_called_once_with( + f"\t\tWeighted Threat Level: {result}", 3, 0 + ) + + +@pytest.mark.parametrize( + "ip, twid, flow_datetime, accumulated_threat_level, blocked", + [ + ("192.168.1.100", 1, "2023/10/26 10:10:10", 0.8, True), + ("10.0.0.100", 2, "2023/10/26 11:11:11", 1.0, False), + ], +) +def test_log_alert( + ip, + twid, + flow_datetime, + accumulated_threat_level, + blocked, +): + worker = ModuleFactory().create_evidence_handler_worker_obj() + worker.add_alert_to_json_log_file = Mock() + worker.add_to_log_file = Mock() + alert = Alert( + profile=ProfileID(ip), + timewindow=TimeWindow(twid), + last_evidence=Mock(), + accumulated_threat_level=accumulated_threat_level, + last_flow_datetime=flow_datetime, + ) + + worker.log_alert(alert, blocked=blocked) + + worker.add_alert_to_json_log_file.assert_called_once() + assert flow_datetime in worker.add_to_log_file.call_args[0][0] + assert str(twid) in worker.add_to_log_file.call_args[0][0] diff --git a/tests/unit/slips_files/core/test_evidence_logger.py b/tests/unit/slips_files/core/test_evidence_logger.py index ef45bcb82d..32e9244ff4 100644 --- a/tests/unit/slips_files/core/test_evidence_logger.py +++ b/tests/unit/slips_files/core/test_evidence_logger.py @@ -2,7 +2,7 @@ # SPDX-License-Identifier: GPL-2.0-only import pytest import os -from unittest.mock import MagicMock, patch, Mock +from unittest.mock import MagicMock, patch, Mock, call import queue import threading @@ -12,26 +12,48 @@ @pytest.mark.parametrize( "output_dir, file_to_clean, file_exists", [ - # testcase1: File doesn't exist ("/tmp", "nonexistent.log", False), - # testcase2: File exists ("/tmp", "existing.log", True), + ("/tmp", "/var/log/app.log", True), ], ) def test_clean_file(output_dir, file_to_clean, file_exists): logger = ModuleFactory().create_evidence_loggr_obj() + with patch("os.path.exists") as mock_exists, patch( - "builtins.open" - ) as mock_open: + "os.makedirs" + ) as mock_makedirs, patch("builtins.open") as mock_open: + mock_exists.return_value = file_exists + mock_file = Mock() - mock_open.return_value = mock_file + truncate_handle = Mock() + mock_open.side_effect = ( + [truncate_handle, mock_file] if file_exists else [mock_file] + ) result = logger.clean_file(output_dir, file_to_clean) - expected_path = os.path.join(output_dir, file_to_clean) + expected_path = ( + file_to_clean + if os.path.isabs(file_to_clean) + else os.path.join(output_dir, file_to_clean) + ) + expected_dir = os.path.dirname(expected_path) + mock_exists.assert_called_once_with(expected_path) - mock_open.assert_called_with(expected_path, "a") + mock_makedirs.assert_called_once_with(expected_dir, exist_ok=True) + + if file_exists: + assert mock_open.call_args_list == [ + call(expected_path, "w"), + call(expected_path, "a"), + ] + truncate_handle.close.assert_called_once_with() + else: + assert mock_open.call_args_list == [ + call(expected_path, "a"), + ] assert result == mock_file diff --git a/tests/unit/slips_files/core/test_profiler.py b/tests/unit/slips_files/core/test_profiler.py index 8fee317189..86c73297dc 100644 --- a/tests/unit/slips_files/core/test_profiler.py +++ b/tests/unit/slips_files/core/test_profiler.py @@ -26,22 +26,20 @@ def test_mark_process_as_done_processing(monkeypatch): @pytest.mark.parametrize( - "msg_from_queue, handler_obj, should_stop_side_effect, expected_start_workers, expect_print_called", + "msg_from_queue, handler_obj, expected_start_workers", [ - # Case 1: triggers all branches - ({"line": {"f1": "v1"}}, Mock(), [False, True], 5, False), + # Case 1: valid input starts the default profiler workers + ({"line": {"f1": "v1"}}, Mock(), 3), # Case 2: unsupported input type, no input_handler_obj - ({"line": {"f1": "v1"}}, None, [True], 0, True), + ({"line": {"f1": "v1"}}, None, 0), # Case 3: empty queue initially, then valid msg - ({"line": {"f1": "v1"}}, Mock(), [False, True], 5, False), + (None, Mock(), 3), ], ) def test_main( msg_from_queue, handler_obj, - should_stop_side_effect, expected_start_workers, - expect_print_called, ): profiler = ModuleFactory().create_profiler_obj() profiler.last_worker_id = 0 @@ -52,9 +50,7 @@ def test_main( profiler.store_flows_read_per_second = Mock() profiler._update_lines_read_by_all_workers = Mock() profiler.print = Mock() - - # Mock should_stop - profiler.should_stop = Mock(side_effect=should_stop_side_effect) + profiler.profiler_monitor_thread = Mock() # Handle empty queue case if msg_from_queue is None: @@ -69,18 +65,23 @@ def test_main( profiler.profiler_queue = Mock() profiler.workers = [] - with patch("time.sleep"): + with ( + patch("time.sleep"), + patch("slips_files.core.profiler.utils.start_thread") as start_thread, + ): profiler.main() if handler_obj: - handler_obj.process_line.assert_called_once_with( - msg_from_queue["line"] + handler_obj.process_line.assert_called_once_with({"f1": "v1"}) + start_thread.assert_called_once_with( + profiler.profiler_monitor_thread, profiler.db ) assert ( profiler.start_profiler_worker.call_count == expected_start_workers ) else: profiler.print.assert_called_once() + start_thread.assert_not_called() assert profiler.start_profiler_worker.call_count == 0 @@ -91,10 +92,23 @@ def test_shutdown_gracefully(monkeypatch): Mock(received_lines=20), Mock(received_lines=3), ] + profiler.stop_profiler_workers = Mock() + profiler.aid_queue = Mock() + profiler.stop_aid_manager_event = Mock() + profiler.aid_manager = Mock() + profiler.profiler_queue = Mock() + profiler.profiler_monitor_thread = Mock() profiler.mark_self_as_done_processing = Mock() - - # monkeypatch.setattr(profiler, "print", Mock()) profiler.shutdown_gracefully() + + profiler.stop_profiler_workers.assert_called_once() + profiler.aid_queue.put.assert_called_once_with("stop") + profiler.stop_aid_manager_event.set.assert_called_once() + profiler.aid_manager.shutdown.assert_called_once() + profiler.profiler_queue.cancel_join_thread.assert_called_once() + profiler.profiler_queue.close.assert_called_once() + profiler.aid_queue.cancel_join_thread.assert_called_once() + profiler.aid_queue.close.assert_called_once() profiler.print.assert_called_with("Stopping.", log_to_logfiles_only=True) profiler.mark_self_as_done_processing.assert_called_once() diff --git a/tests/unit/slips_files/core/test_profiler_worker.py b/tests/unit/slips_files/core/test_profiler_worker.py index 13ec0f6fb6..8477719223 100644 --- a/tests/unit/slips_files/core/test_profiler_worker.py +++ b/tests/unit/slips_files/core/test_profiler_worker.py @@ -1,29 +1,51 @@ # SPDX-FileCopyrightText: 2021 Sebastian Garcia # SPDX-License-Identifier: GPL-2.0-only -"""Unit test for slips_files/core/iperformance_profiler.py""" -import queue -from unittest.mock import Mock, MagicMock +"""Unit tests for slips_files/core/profiler_worker.py.""" -from tests.module_factory import ModuleFactory -from tests.unit.common_test_utils import do_nothing -import pytest +import csv import json -from slips_files.core.profiler import SUPPORTED_INPUT_TYPES, SEPARATORS -from slips_files.core.flows.zeek import Conn -import ipaddress -from unittest.mock import patch +from unittest.mock import Mock, patch + +import pytest + from slips_files.common.input_type import InputType +from slips_files.core.flows.zeek import Conn +from slips_files.core.profiler import SEPARATORS, SUPPORTED_INPUT_TYPES +from tests.module_factory import ModuleFactory +from tests.unit.common_test_utils import do_nothing -# get zeek flow def get_zeek_flow(file, flow_type): - # returns the first flow in the given file - with open(file) as f: + with open(file, encoding="utf-8") as f: sample_flow = f.readline().replace("\n", "") sample_flow = json.loads(sample_flow) - sample_flow = {"data": sample_flow, "type": flow_type, "interface": "eth0"} - return sample_flow + return {"data": sample_flow, "type": flow_type, "interface": "eth0"} + + +def make_conn(**overrides): + data = { + "starttime": "1.0", + "uid": "1234", + "saddr": "192.168.1.1", + "daddr": "8.8.8.8", + "dur": 5, + "proto": "TCP", + "appproto": "dhcp", + "sport": 80, + "dport": 88, + "spkts": 20, + "dpkts": 20, + "sbytes": 20, + "dbytes": 20, + "smac": "", + "dmac": "", + "state": "Established", + "history": "", + "interface": "eth0", + } + data.update(overrides) + return Conn(**data) @pytest.mark.parametrize( @@ -37,14 +59,10 @@ def get_zeek_flow(file, flow_type): ("dataset/test9-mixed-zeek-dir/files.log", "files.log"), ], ) -def test_process_line_zeek_json( - file, - flow_type, -): +def test_process_line_zeek_json(file, flow_type): profiler = ModuleFactory().create_profiler_worker_obj() profiler.symbol = Mock() profiler.db.get_timewindow = Mock(return_value="timewindow1") - # we're testing another functionality here profiler.whitelist.is_whitelisted_flow = do_nothing profiler.input_type = InputType.ZEEK profiler.input_handler = SUPPORTED_INPUT_TYPES[profiler.input_type]( @@ -52,350 +70,321 @@ def test_process_line_zeek_json( ) profiler.separator = SEPARATORS[profiler.input_type] - sample_flow = get_zeek_flow(file, flow_type) - # required to get a flow object to call add_flow_to_profile on - flow, err = profiler.input_handler.process_line(sample_flow) + flow, err = profiler.input_handler.process_line( + get_zeek_flow(file, flow_type) + ) assert not err assert flow -def test_get_rev_profile(): +def test_read_configuration(): profiler = ModuleFactory().create_profiler_worker_obj() - flow: Conn = Conn( - starttime="1.0", - uid="1234", - saddr="192.168.1.1", - daddr="8.8.8.8", - dur=5, - proto="TCP", - appproto="dhcp", - sport=80, - dport=88, - spkts=20, - dpkts=20, - sbytes=20, - dbytes=20, - smac="", - dmac="", - state="Established", - history="", - ) + profiler.conf.client_ips.return_value = ["192.168.1.1", "10.0.0.1"] + profiler.conf.local_whitelist_path.return_value = "path/to/whitelist" + profiler.conf.ts_format.return_value = "unixtimestamp" + profiler.conf.analysis_direction.return_value = "all" + profiler.conf.label.return_value = "malicious" + profiler.conf.get_tw_width_in_seconds.return_value = 1.0 + profiler.conf.generate_performance_plots.return_value = True - profiler.db.get_timewindow.return_value = "timewindow1" - assert profiler.get_rev_profile(flow) == ("profile_8.8.8.8", "timewindow1") - - -def test_get_rev_profile_no_daddr( - flow, -): - profiler = ModuleFactory().create_profiler_worker_obj() - flow.daddr = None - assert profiler.get_rev_profile(flow) == (False, False) + profiler.read_configuration() + assert profiler.client_ips == ["192.168.1.1", "10.0.0.1"] + assert profiler.local_whitelist_path == "path/to/whitelist" + assert profiler.timeformat == "unixtimestamp" + assert profiler.analysis_direction == "all" + assert profiler.label == "malicious" + assert profiler.width == 1.0 + assert profiler.generate_performance_plots is True -def test_get_rev_profile_existing_profileid(): - profiler = ModuleFactory().create_profiler_worker_obj() - flow: Conn = Conn( - starttime="1.0", - uid="1234", - saddr="192.168.1.1", - daddr="8.8.8.8", - dur=5, - proto="TCP", - appproto="dhcp", - sport=80, - dport=88, - spkts=20, - dpkts=20, - sbytes=20, - dbytes=20, - smac="", - dmac="", - state="Established", - history="", - ) - profiler.db.get_timewindow.return_value = "existing_timewindow" - assert profiler.get_rev_profile(flow) == ( - "profile_8.8.8.8", - "existing_timewindow", - ) +def test_get_slips_start_time_uses_db_value(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.db.get_slips_start_time.return_value = "123.5" + assert profiler._get_slips_start_time() == 123.5 -def test_get_rev_profile_no_timewindow(): - profiler = ModuleFactory().create_profiler_worker_obj() - flow: Conn = Conn( - starttime="1.0", - uid="1234", - saddr="192.168.1.1", - daddr="8.8.8.8", - dur=5, - proto="TCP", - appproto="dhcp", - sport=80, - dport=88, - spkts=20, - dpkts=20, - sbytes=20, - dbytes=20, - smac="", - dmac="", - state="Established", - history="", - ) - profiler.db.get_timewindow.return_value = None +@patch("slips_files.core.profiler_worker.time.time", return_value=99.0) +def test_get_slips_start_time_falls_back_to_now(mock_time): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.db.get_slips_start_time.return_value = "invalid" + mock_time.reset_mock() - profile_id, tw_id = profiler.get_rev_profile(flow) - assert profile_id == "profile_8.8.8.8" - assert tw_id is None + assert profiler._get_slips_start_time() == 99.0 + mock_time.assert_called_once() @pytest.mark.parametrize( - "client_ips, expected_private_ips", + "name, expected_prefix", [ - (["192.168.1.1", "10.0.0.1"], ["192.168.1.1", "10.0.0.1"]), - (["8.8.8.8", "1.1.1.1"], []), - (["192.168.1.1", "8.8.8.8"], ["192.168.1.1"]), + ("ProfilerWorker_Process_2", "profiler_worker_2"), + ("ProfilerWorker", "profilerworker"), + ("mock_name", "mock_name"), ], ) -def test_get_private_client_ips(client_ips, expected_private_ips, monkeypatch): +def test_get_latency_filename_prefix(name, expected_prefix): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.client_ips = client_ips - with patch( - "slips_files.core.profiler_worker.utils.is_private_ip" - ) as mock_is_private_ip: + profiler.name = name + + assert profiler._get_latency_filename_prefix() == expected_prefix + + +def test_initialize_latency_logfile_creates_header(tmp_path): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.latency_logfile = str(tmp_path / "latency" / "worker.csv") - def is_private_ip(ip): - ip_obj = ipaddress.ip_address(ip) - return ipaddress.ip_address(ip_obj).is_private + profiler._initialize_latency_logfile() - mock_is_private_ip.side_effect = is_private_ip + with open(profiler.latency_logfile, encoding="utf-8") as f: + rows = list(csv.reader(f)) - private_ips = profiler.get_private_client_ips() - assert set(private_ips) == set(expected_private_ips) + assert rows == [["timestamp_now", "flow_uid", "latency_in_seconds"]] -def test_convert_starttime_to_epoch(): +def test_initialize_latency_logfile_is_noop_when_file_exists(tmp_path): profiler = ModuleFactory().create_profiler_worker_obj() - starttime = "2023-04-04 12:00:00" + logfile = tmp_path / "worker.csv" + logfile.write_text("existing\n", encoding="utf-8") + profiler.latency_logfile = str(logfile) - with patch( - "slips_files.core.profiler_worker.utils.convert_ts_format" - ) as mock_convert_ts_format: - mock_convert_ts_format.return_value = 1680604800 + profiler._initialize_latency_logfile() - converted = profiler.convert_starttime_to_unix_ts(starttime) + assert logfile.read_text(encoding="utf-8") == "existing\n" - mock_convert_ts_format.assert_called_once_with( - "2023-04-04 12:00:00", "unixtimestamp" - ) - assert converted == 1680604800 +@patch("slips_files.core.profiler_worker.time.time", side_effect=[0.0, 120.0]) +def test_log_flow_latency_appends_row(mock_time, tmp_path): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.generate_performance_plots = True + profiler.slips_start_time = 100.0 + profiler.latency_logfile = str(tmp_path / "latency.csv") + profiler._initialize_latency_logfile() + flow = Mock(uid="flow-1") -@pytest.mark.parametrize( - "saddr, localnet_cache, running_non_stop, expected_result", - [ - ("192.168.1.1", {}, True, True), - ("192.168.1.1", {"eth0": "some_ip"}, True, False), - ("8.8.8.8", {"default": "ip"}, False, False), - ], + profiler._log_flow_latency(flow, "110") + + with open(profiler.latency_logfile, encoding="utf-8") as f: + rows = list(csv.reader(f)) + + assert rows[1] == ["20.0", "flow-1", "10"] + + +def test_log_flow_latency_skips_invalid_starttime(tmp_path): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.generate_performance_plots = True + profiler.latency_logfile = str(tmp_path / "latency.csv") + profiler._initialize_latency_logfile() + + profiler._log_flow_latency(Mock(uid="flow-1"), "invalid") + + with open(profiler.latency_logfile, encoding="utf-8") as f: + rows = list(csv.reader(f)) + + assert len(rows) == 1 + + +@patch( + "slips_files.core.profiler_worker.time.time", side_effect=[0.0, 2.0, 4.5] ) -def test_should_set_localnet( - saddr, localnet_cache, running_non_stop, expected_result -): +def test_update_modified_tws_batches_then_flushes(mock_time): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.client_ips = [] - profiler.db.is_running_non_stop = Mock(return_value=running_non_stop) + profiler._modified_tws = {} + profiler._time_to_update_modified_tws = 3.0 + profiler._modified_timewindows_update_period = 3 + flow1 = Mock(starttime="1") + flow2 = Mock(starttime="2") - flow = Mock() - flow.saddr = saddr - flow.interface = "eth0" + profiler._update_modified_tws_in_the_db("profile1", "tw1", flow1) + profiler._update_modified_tws_in_the_db("profile2", "tw2", flow2) - profiler.localnet_cache = localnet_cache - assert profiler.should_set_localnet(flow) == expected_result + profiler.db.mark_profile_tw_as_modified.assert_called_once_with( + {"profile1_tw1": "1", "profile2_tw2": "2"} + ) + assert profiler._modified_tws == {} + assert profiler._time_to_update_modified_tws == 7.5 -@patch("slips_files.core.profiler.ConfigParser") -def test_read_configuration( - mock_config_parser, -): +def test_get_rev_profile(): profiler = ModuleFactory().create_profiler_worker_obj() - mock_conf = mock_config_parser.return_value + flow = make_conn() + profiler.db.get_timewindow.return_value = "timewindow1" - mock_conf.local_whitelist_path.return_value = "path/to/whitelist" - mock_conf.ts_format.return_value = "unixtimestamp" - mock_conf.analysis_direction.return_value = "all" - mock_conf.label.return_value = "malicious" - mock_conf.get_tw_width_in_seconds.return_value = 1.0 - mock_conf.client_ips.return_value = ["192.168.1.1", "10.0.0.1"] - profiler.conf = mock_conf - profiler.read_configuration() + assert profiler.get_rev_profile(flow) == ("profile_8.8.8.8", "timewindow1") + profiler.db.add_profile.assert_called_once_with("profile_8.8.8.8", "1.0") - assert profiler.local_whitelist_path == "path/to/whitelist" - assert profiler.timeformat == "unixtimestamp" - assert profiler.analysis_direction == "all" - assert profiler.label == "malicious" - assert profiler.width == 1.0 - assert profiler.client_ips == ["192.168.1.1", "10.0.0.1"] + +def test_get_rev_profile_no_daddr(): + profiler = ModuleFactory().create_profiler_worker_obj() + flow = make_conn(daddr=None) + + assert profiler.get_rev_profile(flow) == (False, False) -def test_add_flow_to_profile_unsupported_flow(): +def test_convert_starttime_to_unix_ts_returns_input_for_unix_timestamp(): profiler = ModuleFactory().create_profiler_worker_obj() + + assert ( + profiler.convert_starttime_to_unix_ts("1712500000.0") == "1712500000.0" + ) + + +def test_convert_starttime_to_unix_ts_converts_formatted_timestamp(): + profiler = ModuleFactory().create_profiler_worker_obj() + + with patch( + "slips_files.core.profiler_worker.utils.convert_ts_format", + return_value=1680604800, + ) as mock_convert: + assert ( + profiler.convert_starttime_to_unix_ts("2023-04-04 12:00:00") + == 1680604800 + ) + + mock_convert.assert_called_once_with( + "2023-04-04 12:00:00", "unixtimestamp" + ) + + +def test_convert_starttime_to_unix_ts_returns_original_on_error(): + profiler = ModuleFactory().create_profiler_worker_obj() + + with patch( + "slips_files.core.profiler_worker.utils.convert_ts_format", + side_effect=ValueError, + ): + assert ( + profiler.convert_starttime_to_unix_ts("invalid-ts") == "invalid-ts" + ) + + profiler.print.assert_called_once() + + +def test_get_aid_and_store_flow_in_the_db_submits_only_for_conn_handler(): + profiler = ModuleFactory().create_profiler_worker_obj() + handle_conn = Mock() + other_handler = Mock() flow = Mock() - flow.type_ = "unsupported" - flow_parser = Mock() - flow_parser.is_supported_flow.return_value = False - result = profiler.add_flow_to_profile(flow) - assert result is False + profiler.get_aid_and_store_flow_in_the_db( + handle_conn, handle_conn, flow, "profile", "tw1" + ) + profiler.get_aid_and_store_flow_in_the_db( + other_handler, handle_conn, flow, "profile", "tw1" + ) + + profiler.aid_manager.submit_aid_task.assert_called_once_with( + flow, "profile", "tw1", "benign" + ) @patch("slips_files.core.profiler_worker.FlowHandler") -def test_store_features_going_out(mock_flowhandler): +def test_store_features_going_out_conn_flow(mock_flow_handler): profiler = ModuleFactory().create_profiler_worker_obj() profiler.get_aid_and_store_flow_in_the_db = Mock() + profiler._update_modified_tws_in_the_db = Mock() + flow = make_conn(type_="conn") - flow = Mock(type_="conn") + assert ( + profiler.store_features_going_out(flow, "profile_test", "tw1") is True + ) - profileid = "profile_test" - twid = "timewindow1" - is_stored = profiler.store_features_going_out(flow, profileid, twid) - assert is_stored - mock_flowhandler.return_value.handle_conn.assert_called_once() + mock_flow_handler.return_value.handle_conn.assert_called_once() profiler.get_aid_and_store_flow_in_the_db.assert_called_once() - profiler.db.mark_profile_tw_as_modified.assert_called_once() + profiler._update_modified_tws_in_the_db.assert_called_once_with( + "profile_test", "tw1", flow + ) -def test_store_features_going_in_non_conn_flow(): +@patch("slips_files.core.profiler_worker.FlowHandler") +def test_store_features_going_out_matches_substring_type(mock_flow_handler): profiler = ModuleFactory().create_profiler_worker_obj() - flow = Mock(type_="dns", saddr="192.168.1.1", dport=53, proto="UDP") - profileid = "profile_test_dns" - twid = "tw_test_dns" - profiler.store_features_going_in(profileid, twid, flow) - profiler.db.add_tuple.assert_not_called() - profiler.db.add_ips.assert_not_called() - profiler.db.add_port.assert_not_called() - profiler.db.add_flow.assert_not_called() - profiler.db.mark_profile_tw_as_modified.assert_not_called() + profiler.get_aid_and_store_flow_in_the_db = Mock() + profiler._update_modified_tws_in_the_db = Mock() + flow = make_conn(type_="conn.log") + + assert ( + profiler.store_features_going_out(flow, "profile_test", "tw1") is True + ) + + mock_flow_handler.return_value.handle_conn.assert_called_once() @patch("slips_files.core.profiler_worker.FlowHandler") def test_store_features_going_out_unsupported_type(mock_flow_handler): profiler = ModuleFactory().create_profiler_worker_obj() - flow = Mock(type_="unsupported_type") - profileid = "profile_test" - twid = "twid_test" - result = profiler.store_features_going_out(flow, profileid, twid) + assert ( + profiler.store_features_going_out( + Mock(type_="unsupported", starttime="1"), "profile_test", "tw1" + ) + is False + ) + mock_flow_handler.return_value.handle_conn.assert_not_called() - assert result is False -def test_handle_in_flows_valid_daddr(): +def test_store_features_going_in_stores_conn_flow(): profiler = ModuleFactory().create_profiler_worker_obj() - flow = Mock(type_="conn", daddr="8.8.8.8") - profiler.get_rev_profile = Mock(return_value=("rev_profile", "rev_twid")) - profiler.store_features_going_in = Mock() + profiler.symbol.compute = Mock() + profiler.symbol.compute.return_value = "symbol" + profiler._update_modified_tws_in_the_db = Mock() + flow = make_conn(type_="conn") - profiler.handle_in_flow(flow) + profiler.store_features_going_in("profile_test", "tw1", flow) - profiler.get_rev_profile.assert_called_once() - profiler.store_features_going_in.assert_called_once_with( - "rev_profile", "rev_twid", flow + profiler.db.add_tuple.assert_called_once() + profiler.db.add_ips.assert_called_once() + profiler.aid_manager.submit_aid_task.assert_called_once_with( + flow, "profile_test", "tw1", profiler.label + ) + profiler._update_modified_tws_in_the_db.assert_called_once_with( + "profile_test", "tw1", flow ) -@pytest.mark.parametrize( - "client_ips, saddr, expected_cidr", - [ - ( - [ipaddress.IPv4Network("192.168.1.0/24")], - "10.0.0.1", - "192.168.1.0/24", - ), - ( - [ipaddress.IPv4Network("172.16.0.0/16")], - "10.0.0.1", - "172.16.0.0/16", - ), - ([], "10.0.0.1", "10.0.0.0/8"), - ], -) -def test_get_local_net(client_ips, saddr, expected_cidr): +def test_store_features_going_in_skips_unsupported_flow(): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.args.interface = None - flow = Mock() - flow.saddr = saddr - - if not client_ips: - with patch.object( - profiler, "get_private_client_ips", return_value=client_ips - ), patch( - "slips_files.common.slips_utils.Utils.get_cidr_of_private_ip", - return_value="10.0.0.0/8", - ): - local_net = profiler.get_local_net_of_flow(flow) - else: - with patch.object( - profiler, "get_private_client_ips", return_value=client_ips - ): - local_net = profiler.get_local_net_of_flow(flow) - - assert local_net == {"default": expected_cidr} - - -def test_get_local_net_from_flow(): - profiler = ModuleFactory().create_profiler_worker_obj() - profiler.args.interface = None - with patch.object( - profiler, "get_private_client_ips", return_value=[] - ), patch( - "slips_files.common.slips_utils.Utils.get_cidr_of_private_ip", - return_value="10.0.0.0/8", - ): - flow = Mock() - flow.saddr = "10.0.0.1" - local_net = profiler.get_local_net_of_flow(flow) + profiler.store_features_going_in( + "profile_test", "tw1", Mock(type_="dns", saddr="192.168.1.1") + ) - assert local_net == {"default": "10.0.0.0/8"} + profiler.db.add_tuple.assert_not_called() + profiler.aid_manager.submit_aid_task.assert_not_called() -def test_handle_setting_local_net_when_already_set(): +def test_store_features_going_in_skips_invalid_source_ip(): profiler = ModuleFactory().create_profiler_worker_obj() - mock_lock = MagicMock() - mock_lock.__enter__.return_value = None - mock_lock.__exit__.return_value = None - profiler.handle_setting_local_net_lock = mock_lock + profiler.symbol.compute = Mock(return_value="symbol") - local_net = "192.168.1.0/24" - profiler.should_set_localnet = Mock(return_value=False) - profiler.localnet_cache = {"default": local_net} - flow = Mock() - profiler.handle_setting_local_net(flow) - profiler.db.set_local_network.assert_not_called() + profiler.store_features_going_in( + "profile_test", "tw1", Mock(type_="conn", saddr="not-an-ip") + ) + + profiler.db.add_tuple.assert_not_called() -def test_handle_setting_local_net(): +def test_handle_in_flow_stores_reverse_profile(): profiler = ModuleFactory().create_profiler_worker_obj() - mock_lock = MagicMock() - mock_lock.__enter__.return_value = None - mock_lock.__exit__.return_value = None - profiler.handle_setting_local_net_lock = mock_lock + flow = make_conn(type_="conn") + profiler.get_rev_profile = Mock(return_value=("rev_profile", "rev_twid")) + profiler.store_features_going_in = Mock() - local_net = "192.168.1.0/24" - profiler.should_set_localnet = Mock(return_value=True) - profiler.get_local_net_of_flow = Mock(return_value={"default": local_net}) - profiler.get_local_net = Mock(return_value=local_net) - profiler.db.is_running_non_stop = Mock(return_value=False) + profiler.handle_in_flow(flow) - flow = Mock() - flow.saddr = "192.168.1.1" + profiler.store_features_going_in.assert_called_once_with( + "rev_profile", "rev_twid", flow + ) + + +def test_handle_in_flow_skips_software_flows(): + profiler = ModuleFactory().create_profiler_worker_obj() - profiler.handle_setting_local_net(flow) - profiler.db.set_local_network.assert_called_once_with(local_net, "default") + profiler.handle_in_flow(Mock(type_="software")) + + profiler.db.add_profile.assert_not_called() @patch("slips_files.core.profiler_worker.utils.is_private_ip") @@ -404,33 +393,11 @@ def test_get_gateway_info_sets_mac_and_ip( mock_is_ignored_ip, mock_is_private_ip ): profiler = ModuleFactory().create_profiler_worker_obj() - # mac not detected, ip not detected - profiler.is_gw_info_detected = Mock() - profiler.is_gw_info_detected.side_effect = [False, False] + profiler.is_gw_info_detected = Mock(side_effect=[False, False]) + profiler.get_gw_ip_using_gw_mac = Mock(return_value="8.8.8.1") mock_is_private_ip.return_value = True mock_is_ignored_ip.return_value = False - profiler.get_gw_ip_using_gw_mac = Mock() - profiler.get_gw_ip_using_gw_mac.return_value = "8.8.8.1" - flow: Conn = Conn( - starttime="1.0", - uid="1234", - saddr="192.168.1.1", - daddr="8.8.8.8", - dur=5, - proto="TCP", - appproto="dhcp", - sport=80, - dport=88, - spkts=20, - dpkts=20, - sbytes=20, - dbytes=20, - smac="", - dmac="00:11:22:33:44:55", - state="Established", - history="", - interface="eth0", - ) + flow = make_conn(dmac="00:11:22:33:44:55") profiler.get_gateway_info(flow) @@ -438,55 +405,43 @@ def test_get_gateway_info_sets_mac_and_ip( profiler.db.set_default_gateway.assert_any_call("IP", "8.8.8.1", "eth0") -@patch("slips_files.core.profiler_worker.utils.is_private_ip") -def test_get_gateway_info_no_mac_detected(mock_is_private_ip): +def test_get_gateway_info_skips_flows_without_dmac(): profiler = ModuleFactory().create_profiler_worker_obj() + flow = Mock(spec=["interface"]) + flow.interface = "eth0" - # mac not detected, ip not detected - profiler.is_gw_info_detected = Mock() - profiler.is_gw_info_detected.side_effect = [False, False] - mock_is_private_ip.return_value = False - flow: Conn = Conn( - starttime="1.0", - uid="1234", - saddr="192.168.1.1", - daddr="8.8.8.8", - dur=5, - proto="TCP", - appproto="dhcp", - sport=80, - dport=88, - spkts=20, - dpkts=20, - sbytes=20, - dbytes=20, - smac="", - dmac="00:11:22:33:44:55", - state="Established", - history="", - ) profiler.get_gateway_info(flow) - # mac and ip should not be set profiler.db.set_default_gateway.assert_not_called() - profiler.print.assert_not_called() -def test_get_gateway_info_mac_detected_but_no_ip(): +@patch( + "slips_files.core.profiler_worker.utils.is_private_ip", return_value=False +) +def test_get_gateway_info_does_not_set_gateway_for_non_private_source(_mock): profiler = ModuleFactory().create_profiler_worker_obj() - flow = Mock() - flow.dmac = "123" - # mac detected, ip not detected profiler.is_gw_info_detected = Mock() - profiler.is_gw_info_detected.side_effect = [True, False] - profiler.get_gw_ip_using_gw_mac = Mock() - profiler.get_gw_ip_using_gw_mac.return_value = None + profiler.is_gw_info_detected.side_effect = [False, False] - profiler.get_gateway_info(flow) + profiler.get_gateway_info(make_conn(dmac="00:11:22:33:44:55")) - # assertions for mac profiler.db.set_default_gateway.assert_not_called() - profiler.print.assert_not_called() + + +def test_get_gw_ip_using_gw_mac_prefers_ipv4(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.db.get_ip_of_mac.return_value = json.dumps( + ["2001:db8::1", "192.168.0.1"] + ) + + assert profiler.get_gw_ip_using_gw_mac("mac") == "192.168.0.1" + + +def test_get_gw_ip_using_gw_mac_returns_none_when_missing(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.db.get_ip_of_mac.return_value = None + + assert profiler.get_gw_ip_using_gw_mac("mac") is None @pytest.mark.parametrize( @@ -496,129 +451,262 @@ def test_get_gateway_info_mac_detected_but_no_ip(): ("ip", "gw_ips", "get_gateway_ip", "192.168.1.1"), ], ) -def test_is_gw_info_detected(info_type, attr_name, db_method, db_value): - # create a profiler object using the ModuleFactory +def test_is_gw_info_detected_loads_from_db( + info_type, attr_name, db_method, db_value +): profiler = ModuleFactory().create_profiler_worker_obj() - - # ensure gw_macs / gw_ips exist as dicts setattr(profiler, attr_name, {}) + setattr(profiler.db, db_method, Mock(return_value=db_value)) - # mock the db method - mock_method = Mock(return_value=db_value) - setattr(profiler.db, db_method, mock_method) + assert profiler.is_gw_info_detected(info_type, "eth0") is True + assert getattr(profiler, attr_name)["eth0"] == db_value - # call the function - result = profiler.is_gw_info_detected(info_type, "eth0") - # verify - assert result is True - assert getattr(profiler, attr_name)["eth0"] == db_value - mock_method.assert_called_once_with("eth0") +def test_is_gw_info_detected_uses_cached_value(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.gw_macs = {"eth0": "mac"} + + assert profiler.is_gw_info_detected("mac", "eth0") is True + profiler.db.get_gateway_mac.assert_not_called() def test_is_gw_info_detected_unsupported_info_type(): - # create a profiler object using the ModuleFactory profiler = ModuleFactory().create_profiler_worker_obj() - # test with an unsupported info_type - with pytest.raises(ValueError) as exc_info: - profiler.is_gw_info_detected("unsupported_type", "eth0") + with pytest.raises(ValueError, match="Unsupported info_type"): + profiler.is_gw_info_detected("unsupported", "eth0") + + +@pytest.mark.parametrize( + ("ip", "expected"), + [ + ("224.0.0.1", True), + ("127.0.0.1", True), + ("169.254.1.1", True), + ("240.0.0.1", True), + ("8.8.8.8", False), + ("not-an-ip", True), + ], +) +def test_is_ignored_ip(ip, expected): + profiler = ModuleFactory().create_profiler_worker_obj() - assert str(exc_info.value) == "Unsupported info_type: unsupported_type" + assert profiler.is_ignored_ip(ip) is expected -def test_main_no_msg(): +@pytest.mark.parametrize( + ("starttime", "type_", "expected"), + [ + ("1", "conn", True), + ("1", "http", True), + (None, "conn", False), + ("1", "conn.log", False), + ("1", "unsupported", False), + ], +) +def test_is_supported_flow_type(starttime, type_, expected): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.should_stop_profiler_workers = Mock() - profiler.get_msg_from_queue = Mock() - profiler.add_flow_to_profile = Mock() - profiler.input_handler = Mock() - profiler.print = Mock() - profiler.get_handler_obj = Mock() - profiler.print_traceback = Mock() - - profiler.should_stop_profiler_workers.side_effect = [ - False, - True, - ] # Run loop once - profiler.get_msg_from_queue.return_value = ( - None # Empty message (no message in queue) + + assert ( + profiler._is_supported_flow_type( + Mock(starttime=starttime, type_=type_) + ) + is expected ) - profiler.main() - profiler.get_handler_obj.assert_not_called() - profiler.input_handler.process_line.assert_not_called() - profiler.add_flow_to_profile.assert_not_called() - profiler.print.assert_any_call( - "Module didn't subscribe to new_zeek_fields_line and is trying to get msgs from it." +def test_add_flow_to_profile_returns_false_for_unsupported_flow(): + profiler = ModuleFactory().create_profiler_worker_obj() + + assert ( + profiler.add_flow_to_profile( + Mock( + type_="unsupported", + starttime="1", + saddr="1.1.1.1", + daddr="2.2.2.2", + ) + ) + is False + ) + + +def test_add_flow_to_profile_rejects_invalid_addresses(): + profiler = ModuleFactory().create_profiler_worker_obj() + flow = Mock(type_="conn", starttime="1", saddr="bad", daddr=None) + + assert profiler.add_flow_to_profile(flow) is False + + +def test_add_flow_to_profile_stops_after_whitelist(): + profiler = ModuleFactory().create_profiler_worker_obj() + flow = make_conn(type_="conn") + profiler.convert_starttime_to_unix_ts = Mock(return_value="2.0") + profiler._log_flow_latency = Mock() + profiler.get_gateway_info = Mock() + profiler.whitelist.is_whitelisted_flow = Mock(return_value=True) + profiler.store_features_going_out = Mock() + assert profiler.add_flow_to_profile(flow) is True + + profiler.db.add_profile.assert_not_called() + profiler.store_features_going_out.assert_not_called() + + +def test_add_flow_to_profile_stores_forward_and_reverse_flows(): + profiler = ModuleFactory().create_profiler_worker_obj() + flow = make_conn(type_="conn") + profiler.analysis_direction = "all" + profiler.convert_starttime_to_unix_ts = Mock(return_value="2.0") + profiler._log_flow_latency = Mock() + profiler.get_gateway_info = Mock() + profiler.whitelist.is_whitelisted_flow = Mock(return_value=False) + profiler.store_features_going_out = Mock() + profiler.handle_in_flow = Mock() + profiler.db.get_timewindow.return_value = "tw1" + profiler.db.is_cyst_enabled.return_value = False + + assert profiler.add_flow_to_profile(flow) is True + + profiler.db.add_profile.assert_called_once_with( + "profile_192.168.1.1", "2.0" + ) + profiler.store_features_going_out.assert_called_once_with( + flow, "profile_192.168.1.1", "tw1" ) + profiler.handle_in_flow.assert_called_once_with(flow) + assert flow.starttime == "2.0" -def test_is_stop_msg(monkeypatch): +def test_update_the_files_input_handler_knows_about(): profiler = ModuleFactory().create_profiler_worker_obj() + profiler.input_handler.line_processor_cache = {} + msg = {"data": json.dumps({"conn.log": {"foo": 1}})} + + profiler.update_the_files_input_handler_knows_about(msg) + + assert profiler.input_handler.line_processor_cache == { + "conn.log": {"foo": 1} + } + + +def test_is_stop_msg(): + profiler = ModuleFactory().create_profiler_worker_obj() + assert profiler.is_stop_msg("stop") is True assert profiler.is_stop_msg("not_stop") is False -def test_main_stop_msg_received(): +def test_should_stop_always_returns_false(): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.should_stop = Mock(side_effect=[False, True]) - - profiler.profiler_queue = Mock(spec=queue.Queue) - profiler.profiler_queue.get.return_value = "stop" - stopped = profiler.main() - assert stopped + assert profiler.should_stop() is False -def test_main(): +def test_pre_main_updates_line_processor_cache(): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.should_stop_profiler_workers = Mock() - profiler.get_msg_from_queue = Mock() - profiler.input_handler = Mock() - profiler.add_flow_to_profile = Mock() - profiler.handle_setting_local_net = Mock() - profiler.print = Mock() - profiler.print_traceback = Mock() - profiler.should_stop_profiler_workers.side_effect = [ - False, - True, - ] # Run once - profiler.get_msg_from_queue.return_value = { - "line": {"key": "value"}, - "input_type": InputType.ZEEK, + profiler.name = "ProfilerWorker_Process_2" + profiler.input_handler.line_processor_cache = {} + profiler.db.get_line_processors.return_value = { + "conn.log": json.dumps({"ts": 0}) } - mock_flow = Mock() - profiler.input_handler.process_line = Mock(return_value=(mock_flow, "")) + + profiler.pre_main() + + assert profiler.input_handler.line_processor_cache == { + "conn.log": {"ts": 0} + } + + +def test_main_returns_when_queue_is_empty(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.get_msg = Mock(return_value=None) + profiler.get_msg_from_queue = Mock(return_value=None) + + assert profiler.main() is None + + +def test_main_stops_on_stop_message(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.get_msg = Mock(return_value=None) + profiler.get_msg_from_queue = Mock(return_value="stop") + + assert profiler.main() == 1 + + +def test_main_requeues_unknown_line_processor_until_input_done(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.get_msg = Mock(return_value=None) + msg = {"line": {"foo": "bar"}} + profiler.get_msg_from_queue = Mock(return_value=msg) + profiler.is_input_done_event.is_set.return_value = False + profiler.input_handler.process_line = Mock( + return_value=(None, "unknown line_processor") + ) profiler.main() - profiler.input_handler.process_line.assert_called_once() - profiler.add_flow_to_profile.assert_called_once() - profiler.handle_setting_local_net.assert_called_once() - profiler.db.increment_processed_flows.assert_called_once() + profiler.profiler_queue.put.assert_called_once_with(msg) + profiler.db.increment_processed_flows.assert_not_called() -def test_main_handle_exception(): +def test_main_does_not_requeue_unknown_line_processor_after_input_done(): profiler = ModuleFactory().create_profiler_worker_obj() - profiler.should_stop_profiler_workers = Mock() - profiler.get_msg_from_queue = Mock() - profiler.input_handler = Mock() - profiler.print = Mock() - profiler.print_traceback = Mock() + profiler.get_msg = Mock(return_value=None) + msg = {"line": {"foo": "bar"}} + profiler.get_msg_from_queue = Mock(return_value=msg) + profiler.is_input_done_event.is_set.return_value = True + profiler.input_handler.process_line = Mock( + return_value=(None, "unknown line_processor") + ) - profiler.should_stop_profiler_workers.side_effect = [ - False, - True, - ] # Run loop once - profiler.get_msg_from_queue.return_value = { - "line": {"key": "value"}, - "input_type": "invalid_type", - } - profiler.input_handler.process_line.side_effect = Exception( - "Test exception" + profiler.main() + + profiler.profiler_queue.put.assert_not_called() + + +def test_main_processes_valid_flow_and_records_performance(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.generate_performance_plots = True + profiler.get_msg = Mock(return_value=None) + profiler.get_msg_from_queue = Mock(return_value={"line": {"foo": "bar"}}) + profiler.is_stop_msg = Mock(return_value=False) + flow = Mock() + profiler.input_handler.process_line = Mock(return_value=(flow, None)) + profiler.add_flow_to_profile = Mock() + profiler.localnet_handler.handle_setting_local_net = Mock() + + assert profiler.main() is None + + profiler.add_flow_to_profile.assert_called_once_with(flow) + profiler.localnet_handler.handle_setting_local_net.assert_called_once_with( + flow ) + profiler.db.increment_processed_flows.assert_called_once() + profiler.db.record_flow_per_minute.assert_called_once_with(profiler.name) + + +def test_main_collects_gc_every_10000_flows(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.get_msg = Mock(return_value=None) + profiler.get_msg_from_queue = Mock(return_value={"line": {"foo": "bar"}}) + profiler.input_handler.process_line = Mock(return_value=(Mock(), None)) + profiler.add_flow_to_profile = Mock() + profiler.localnet_handler.handle_setting_local_net = Mock() + profiler.received_lines = 9999 + + with patch("slips_files.core.profiler_worker.gc.collect") as mock_collect: + profiler.main() + + mock_collect.assert_called_once() + + +def test_main_logs_exception(): + profiler = ModuleFactory().create_profiler_worker_obj() + profiler.get_msg = Mock(return_value=None) + profiler.get_msg_from_queue = Mock(return_value={"line": {"foo": "bar"}}) + profiler.input_handler.process_line = Mock(side_effect=Exception("boom")) + profiler.print_traceback = Mock(return_value="traceback") profiler.main() - profiler.print_traceback.assert_called_once() + + profiler.print.assert_called_once()