From a8266a3138f4bf684074ed21d9fe90e0146b9da1 Mon Sep 17 00:00:00 2001 From: ekneg54 Date: Thu, 19 Oct 2023 12:33:40 +0000 Subject: [PATCH] reimplement Amides Metrics --- logprep/metrics/metrics.py | 18 +++- logprep/processor/amides/processor.py | 99 ++++++++++++---------- logprep/util/time_measurement.py | 5 +- tests/unit/processor/amides/test_amides.py | 43 +++++++--- tests/unit/processor/base.py | 21 +++-- 5 files changed, 119 insertions(+), 67 deletions(-) diff --git a/logprep/metrics/metrics.py b/logprep/metrics/metrics.py index fbbd18bcf..426779f04 100644 --- a/logprep/metrics/metrics.py +++ b/logprep/metrics/metrics.py @@ -2,7 +2,7 @@ from abc import ABC, abstractmethod from attr import asdict, define, field, validators -from prometheus_client import CollectorRegistry, Counter, Histogram +from prometheus_client import CollectorRegistry, Counter, Gauge, Histogram def is_public(attribute, _): @@ -74,6 +74,13 @@ def init_tracker(self): buckets=(0.000001, 0.00001, 0.0001, 0.001, 0.01, 0.1, 1), registry=self._registry, ) + if isinstance(self, GaugeMetric): + tracker = Gauge( + name=self.fullname, + documentation=self.description, + labelnames=self.labels.keys(), + registry=self._registry, + ) tracker.labels(**self.labels) self.trackers.update({self.fullname: tracker}) @@ -103,6 +110,15 @@ def __add__(self, other): return self +@define(kw_only=True) +class GaugeMetric(Metric): + trackers: dict = {} + + def __add__(self, other): + self.trackers.get(self.fullname).labels(**self.labels).set(other) + return self + + def calculate_new_average(current_average, next_sample, sample_counter): """Calculate a new average by combining a new sample with a sample counter""" average_multiple = current_average * sample_counter diff --git a/logprep/processor/amides/processor.py b/logprep/processor/amides/processor.py index 6c53789e8..0b777d71a 100644 --- a/logprep/processor/amides/processor.py +++ b/logprep/processor/amides/processor.py @@ -93,12 +93,18 @@ from attr import define, field, validators from logprep.abc.processor import Processor -from logprep.metrics.metrics import calculate_new_average +from logprep.metrics.metrics import ( + CounterMetric, + GaugeMetric, + HistogramMetric, + calculate_new_average, +) from logprep.processor.amides.detection import MisuseDetector, RuleAttributor from logprep.processor.amides.normalize import CommandLineNormalizer from logprep.processor.amides.rule import AmidesRule from logprep.util.getter import GetterFactory from logprep.util.helper import get_dotted_field_value +from logprep.util.time_measurement import TimeMeasurement class Amides(Processor): @@ -123,42 +129,55 @@ class Config(Processor.Config): class Metrics(Processor.Metrics): """Track statistics specific for Amides processor instances.""" - total_cmdlines: int = 0 + total_cmdlines: CounterMetric = field( + factory=lambda: CounterMetric( + description="Total number of command lines processed.", + name="total_cmdlines", + ) + ) """Total number of command lines processed.""" - new_results: int = 0 + new_results: GaugeMetric = field( + factory=lambda: GaugeMetric( + description="Number of command lines that triggered detection and rule attribution.", + name="new_results", + ) + ) """Number of command lines that triggered detection and rule attribution.""" - cached_results: int = 0 + cached_results: GaugeMetric = field( + factory=lambda: GaugeMetric( + description="Number of command lines that could be resolved from cache.", + name="cached_results", + ) + ) """Number of command lines that could be resolved from cache.""" - num_cache_entries: int = 0 + num_cache_entries: GaugeMetric = field( + factory=lambda: GaugeMetric( + description="Absolute number of current cache entries.", + name="num_cache_entries", + ) + ) """Absolute number of current cache entries.""" - cache_load: float = 0.0 + cache_load: GaugeMetric = field( + factory=lambda: GaugeMetric( + description="Mean processing time of command lines classified by the misuse detector.", + name="cache_load", + ) + ) """Relative cache load.""" - mean_misuse_detection_time: float = 0.0 - """Mean processing time of command lines classified by the misuse detector.""" - _mean_misuse_detection_time_sample_counter: int = 0 - mean_rule_attribution_time: float = 0.0 - """Mean processing time of command lines attributed by the rule attributor.""" - _mean_rule_attribution_time_sample_counter: int = 0 - - def update_mean_misuse_detection_time(self, new_sample: float): - """Updates the mean processing time of the misuse detection.""" - new_mean, new_sample_counter = calculate_new_average( - self.mean_misuse_detection_time, - new_sample, - self._mean_misuse_detection_time_sample_counter, + mean_misuse_detection_time: HistogramMetric = field( + factory=lambda: HistogramMetric( + description="Mean processing time of command lines classified by the misuse detector.", + name="mean_misuse_detection_time", ) - self.mean_misuse_detection_time = new_mean - self._mean_misuse_detection_time_sample_counter = new_sample_counter - - def update_mean_rule_attribution_time(self, new_sample: float): - """Updates the mean processing time of the rule attribution model.""" - new_mean, new_sample_counter = calculate_new_average( - self.mean_rule_attribution_time, - new_sample, - self._mean_rule_attribution_time_sample_counter, + ) + """Mean processing time of command lines classified by the misuse detector.""" + mean_rule_attribution_time: HistogramMetric = field( + factory=lambda: HistogramMetric( + description="Mean processing time of command lines attributed by the rule attributor.", + name="mean_rule_attribution_time", ) - self.mean_rule_attribution_time = new_mean - self._mean_rule_attribution_time_sample_counter = new_sample_counter + ) + """Mean processing time of command lines attributed by the rule attributor.""" __slots__ = ( "_misuse_detector", @@ -229,27 +248,19 @@ def _evaluate_cmdline(self, cmdline: str): return result + @TimeMeasurement.measure_time(metric_name="mean_misuse_detection_time") def _perform_misuse_detection(self, cmdline: str) -> Tuple[bool, float]: - begin = time() result = self._misuse_detector.detect(cmdline) - processing_time = time() - begin - - self.metrics.update_mean_misuse_detection_time(processing_time) - return result + @TimeMeasurement.measure_time(metric_name="mean_rule_attribution_time") def _calculate_rule_attributions(self, cmdline: str) -> List[dict]: - begin = time() attributions = self._rule_attributor.attribute(cmdline) - processing_time = time() - begin - - self.metrics.update_mean_rule_attribution_time(processing_time) - return attributions def _update_cache_metrics(self): cache_info = self._evaluate_cmdline_cached.cache_info() - self.metrics.new_results = cache_info.misses - self.metrics.cached_results = cache_info.hits - self.metrics.num_cache_entries = cache_info.currsize - self.metrics.cache_load = cache_info.currsize / cache_info.maxsize + self.metrics.new_results += cache_info.misses + self.metrics.cached_results += cache_info.hits + self.metrics.num_cache_entries += cache_info.currsize + self.metrics.cache_load += cache_info.currsize / cache_info.maxsize diff --git a/logprep/util/time_measurement.py b/logprep/util/time_measurement.py index a050ae362..b7c5873f8 100644 --- a/logprep/util/time_measurement.py +++ b/logprep/util/time_measurement.py @@ -8,7 +8,7 @@ class TimeMeasurement: """Measures the execution time of functions and adds the results to events via a decorator.""" @staticmethod - def measure_time(): + def measure_time(metric_name: str = "processing_time_per_event"): """Decorate function to measure execution time for function and add results to event.""" def inner_decorator(func): @@ -20,7 +20,8 @@ def inner(*args, **kwargs): # nosemgrep caller = args[0] if func.__name__ in ("_process_rule_tree", "_process_rule"): caller = args[-1] - caller.metrics.processing_time_per_event += processing_time + metric = getattr(caller.metrics, metric_name) + metric += processing_time return result return inner diff --git a/tests/unit/processor/amides/test_amides.py b/tests/unit/processor/amides/test_amides.py index 068999254..be742741b 100644 --- a/tests/unit/processor/amides/test_amides.py +++ b/tests/unit/processor/amides/test_amides.py @@ -25,6 +25,10 @@ class TestAmides(BaseProcessorTestCase): } def test_process_event_malicious_process_command_line(self): + self.object.metrics.total_cmdlines = 0 + self.object.metrics.new_results = 0 + self.object.metrics.num_cache_entries = 0 + self.object.metrics.cache_load = 0.0 self.object.setup() document = { "winlog": { @@ -46,10 +50,12 @@ def test_process_event_malicious_process_command_line(self): assert self.object.metrics.new_results == 1 assert self.object.metrics.num_cache_entries == 1 assert self.object.metrics.cache_load == 0.2 - assert self.object.metrics.mean_misuse_detection_time != 0.0 - assert self.object.metrics.mean_rule_attribution_time != 0.0 def test_process_event_benign_process_command_line(self): + self.object.metrics.total_cmdlines = 0 + self.object.metrics.new_results = 0 + self.object.metrics.num_cache_entries = 0 + self.object.metrics.cache_load = 0.0 self.object.setup() document = { "winlog": { @@ -68,8 +74,6 @@ def test_process_event_benign_process_command_line(self): assert self.object.metrics.new_results == 1 assert self.object.metrics.num_cache_entries == 1 assert self.object.metrics.cache_load == 0.2 - assert self.object.metrics.mean_misuse_detection_time != 0.0 - assert self.object.metrics.mean_rule_attribution_time == 0.0 no_pc_events = [ {"winlog": {"event_id": 6005, "provider_name": "Microsoft-Windows-Sysmon"}}, @@ -80,6 +84,10 @@ def test_process_event_benign_process_command_line(self): @pytest.mark.parametrize("document", no_pc_events) def test_process_event_no_process_creation_events(self, document): + self.object.metrics.total_cmdlines = 0 + self.object.metrics.new_results = 0 + self.object.metrics.num_cache_entries = 0 + self.object.metrics.cache_load = 0.0 self.object.setup() self.object.process(document) @@ -88,10 +96,12 @@ def test_process_event_no_process_creation_events(self, document): assert self.object.metrics.new_results == 0 assert self.object.metrics.num_cache_entries == 0 assert self.object.metrics.cache_load == 0.0 - assert self.object.metrics.mean_misuse_detection_time == 0.0 - assert self.object.metrics.mean_rule_attribution_time == 0.0 def test_process_event_without_command_line_field(self): + self.object.metrics.total_cmdlines = 0 + self.object.metrics.new_results = 0 + self.object.metrics.num_cache_entries = 0 + self.object.metrics.cache_load = 0.0 self.object.setup() document = { "winlog": {"event_id": 1, "provider_name": "Microsoft-Windows-Sysmon"}, @@ -104,10 +114,13 @@ def test_process_event_without_command_line_field(self): assert self.object.metrics.new_results == 0 assert self.object.metrics.num_cache_entries == 0 assert self.object.metrics.cache_load == 0.0 - assert self.object.metrics.mean_misuse_detection_time == 0.0 - assert self.object.metrics.mean_rule_attribution_time == 0.0 def test_classification_results_from_cache(self): + self.object.metrics.total_cmdlines = 0 + self.object.metrics.new_results = 0 + self.object.metrics.cached_results = 0 + self.object.metrics.num_cache_entries = 0 + self.object.metrics.cache_load = 0.0 self.object.setup() document = { "winlog": { @@ -123,12 +136,16 @@ def test_classification_results_from_cache(self): assert other_document.get("amides") == document.get("amides") assert self.object.metrics.total_cmdlines == 2 - assert self.object.metrics.new_results == 1 + # we mock the metrics with integer operations, so the assertions + # are a little bit weird: + # we assert for 2 because we add two times the same cache result + # the underlying metric implementation sets the values instead of adding + # them + assert self.object.metrics.new_results == 2 + assert self.object.metrics.num_cache_entries == 2 + assert self.object.metrics.cache_load == 0.4 + # end strange mock assert self.object.metrics.cached_results == 1 - assert self.object.metrics.num_cache_entries == 1 - assert self.object.metrics.cache_load == 0.2 - assert self.object.metrics.mean_misuse_detection_time != 0.0 - assert self.object.metrics.mean_rule_attribution_time != 0.0 def test_process_event_raise_duplication_error(self, caplog): self.object.setup() diff --git a/tests/unit/processor/base.py b/tests/unit/processor/base.py index c40ecb321..6faf1a3a1 100644 --- a/tests/unit/processor/base.py +++ b/tests/unit/processor/base.py @@ -2,6 +2,7 @@ # pylint: disable=protected-access # pylint: disable=attribute-defined-outside-init +import itertools import json from copy import deepcopy from logging import getLogger @@ -277,14 +278,20 @@ def test_rule_has_metric(self, metric_name, metric_class): metric_instance = getattr(self.object.rules[0].metrics, metric_name) assert isinstance(metric_instance, metric_class) - def test_custom_metrics_are_metric_objects(self): - def asdict_filter(attribute, value): - block_list = ["_labels", "_prefix"] - return not any( - (attribute.name in block_list, value is None, isinstance(value, Callable)) - ) + @staticmethod + def asdict_filter(attribute, value): + """Returns all attributes not in block list or None""" + block_list = ["_labels", "_prefix"] + return not any((attribute.name in block_list, value is None, isinstance(value, Callable))) - metric_attributes = asdict(self.object.metrics, filter=asdict_filter, recurse=False) + def test_custom_metrics_are_metric_objects(self): + metric_attributes = asdict(self.object.metrics, filter=self.asdict_filter, recurse=False) assert all( isinstance(value, Metric) for value in metric_attributes.values() ), "one of the metrics instance attributes is not an instance of type Metric" + + def test_no_metrics_with_same_name(self): + metric_attributes = asdict(self.object.metrics, filter=self.asdict_filter, recurse=False) + pairs = itertools.combinations(metric_attributes.values(), 2) + for metric1, metric2 in pairs: + assert metric1.name != metric2.name, f"{metric1.name} == {metric2.name}"