diff --git a/CHANGELOG.md b/CHANGELOG.md index 78e65bd06..8d2776a6c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,9 @@ ### Breaking * remove AutoRuleCorpusTester +* removes the option to use synchronous `bulk` or `parallel_bulk` operation in favor of `parallel_bulk` in `opensearch_output` +* reimplement error handling by introducing the option to configure an error output + * if no error output is configured, failed event will be dropped ### Features @@ -15,7 +18,11 @@ * make `imagePullPolicy` configurable for helm chart deployments * it is now possible to use Lucene compliant Filter Expressions * make `terminationGracePeriodSeconds` configurable in helm chart values - +* adds ability to configure error output +* adds option `default_op_type` to `opensearch_output` connector to set the default operation for indexing documents (default: index) +* adds option `max_chunk_bytes` to `opensearch_output` connector to set the maximum size of the request in bytes (default: 100MB) +* adds option `error_backlog_size` to logprep configuration to configure the queue size of the error queue +* the opensearch default index is now only used for processed events, errors will be written to the error output, if configured ### Improvements diff --git a/README.md b/README.md index 2511c545b..10b4fd2ed 100644 --- a/README.md +++ b/README.md @@ -84,7 +84,7 @@ log message, based on a configured geo-ip database. Or the `Dropper` deletes fields from the log message. As detailed overview of all processors can be found in the -[processor documentation](https://logprep.readthedocs.io/en/latest/user_manual/configuration/processor.html). +[processor documentation](https://logprep.readthedocs.io/en/latest/configuration/processor.html). To influence the behaviour of those processors, each can be configured with a set of rules. These rules define two things. @@ -147,9 +147,9 @@ kafka-topic. Addionally, you can use the Opensearch or Opensearch output connect messages directly to Opensearch or Opensearch after processing. The details regarding the connectors can be found in the -[input connector documentation](https://logprep.readthedocs.io/en/latest/user_manual/configuration/input.html) +[input connector documentation](https://logprep.readthedocs.io/en/latest/configuration/input.html) and -[output connector documentation](https://logprep.readthedocs.io/en/latest/user_manual/configuration/output.html). +[output connector documentation](https://logprep.readthedocs.io/en/latest/configuration/output.html). ### Configuration @@ -228,7 +228,7 @@ The condition of this rule would check if the field `message` exists in the log. If it does exist then the dropper would delete this field from the log message. Details about the rule language and how to write rules for the processors can be found in the -[rule configuration documentation](https://logprep.readthedocs.io/en/latest/user_manual/configuration/rules.html). +[rule configuration documentation](https://logprep.readthedocs.io/en/latest/configuration/rules.html). ## Getting Started diff --git a/charts/logprep/Chart.yaml b/charts/logprep/Chart.yaml index a5afd7d13..1fcd593ea 100644 --- a/charts/logprep/Chart.yaml +++ b/charts/logprep/Chart.yaml @@ -6,10 +6,10 @@ type: application # This is the chart version. This version number should be incremented each time you make changes # to the chart and its templates, including the app version. # Versions are expected to follow Semantic Versioning (https://semver.org/) -version: "13.4.0" +version: "14.0.0" # This is the version number of the application being deployed. This version number should be # incremented each time you make changes to the application. Versions are not expected to # follow Semantic Versioning. They should reflect the version the application is using. # It is recommended to use it with quotes. -appVersion: "13.1.2" +appVersion: "14.0.0" diff --git a/charts/logprep/templates/deployment.yaml b/charts/logprep/templates/deployment.yaml index 1dd7d7fcd..486fb0b1a 100644 --- a/charts/logprep/templates/deployment.yaml +++ b/charts/logprep/templates/deployment.yaml @@ -54,6 +54,9 @@ spec: - output-config.yaml - logger-config.yaml - exporter-config.yaml + {{- if .Values.error_output }} + - error-output-config.yaml + {{- end }} env: {{- if eq .Values.logger.level "DEBUG" }} - name: DEBUG # to get python stacktrace on error @@ -103,6 +106,11 @@ spec: - name: output-config mountPath: /home/logprep/output-config.yaml subPath: output-config.yaml + {{- if .Values.error_output }} + - name: error-output-config + mountPath: /home/logprep/error-output-config.yaml + subPath: error-output-config.yaml + {{- end }} {{- if .Values.extraMounts }} {{- toYaml .Values.extraMounts | nindent 12 }} {{- end }} @@ -155,6 +163,11 @@ spec: - name: output-config configMap: name: {{ include "logprep.fullname" . }}-output + {{- if .Values.error_output }} + - name: error-output-config + configMap: + name: {{ include "logprep.fullname" . }}-error-output + {{- end }} {{- if .Values.artifacts }} - name: artifacts configMap: diff --git a/charts/logprep/templates/error-output-config.yaml b/charts/logprep/templates/error-output-config.yaml new file mode 100644 index 000000000..fd7df1574 --- /dev/null +++ b/charts/logprep/templates/error-output-config.yaml @@ -0,0 +1,14 @@ +{{- if .Values.error_output }} +--- +apiVersion: v1 +kind: ConfigMap +metadata: + name: {{ include "logprep.fullname" . }}-error-output + labels: + {{- include "logprep.labels" . | nindent 4 }} +data: + error-output-config.yaml: | + error_output: + {{- trimSuffix "_output" .Values.error_output.type | nindent 6}}: + {{- toYaml .Values.error_output | nindent 8}} +{{- end }} diff --git a/charts/logprep/values.yaml b/charts/logprep/values.yaml index f24bdbbab..11a658444 100644 --- a/charts/logprep/values.yaml +++ b/charts/logprep/values.yaml @@ -98,7 +98,7 @@ exporter: argocd.argoproj.io/sync-options: SkipDryRunOnMissingResource=true # Logprep logging configuration. -# See: https://logprep.readthedocs.io/en/latest/user_manual/configuration/index.html#configuration-file-structure +# See: https://logprep.readthedocs.io/en/latest/configuration/index.html#configuration-file-structure # for available configuration options. logger: level: DEBUG @@ -110,7 +110,7 @@ logger: # If the type is `http_input`, an extra service will be populated and the readiness # probe will be set to the health check of the configured http input. # -# See https://logprep.readthedocs.io/en/latest/user_manual/configuration/input.html +# See https://logprep.readthedocs.io/en/latest/configuration/input.html # for available configuration options. # Note: # For the `http_input` endpoints you have to add the endpoint `/health: plaintext` to ensure @@ -123,10 +123,32 @@ input: {} # `type` of the output. For example, if the type is `opensearch_output`, the # name of the output will be `opensearch`. Keep this in mind if you specify # additional outputs in the configurations section. -# See https://logprep.readthedocs.io/en/latest/user_manual/configuration/output.html +# See https://logprep.readthedocs.io/en/latest/configuration/output.html # for available configuration options. output: {} +# The logprep error output connector configuration +# Note: If this is not set, failed events will be dropped. +# Available error outputs are the same as the normal outputs. +# See https://logprep.readthedocs.io/en/latest/configuration/output.html +# Example: +# +# error_output: +# type: confluentkafka_output +# topic: errors +# flush_timeout: 300 +# send_timeout: 0 +# kafka_config: +# bootstrap.servers: 127.0.0.1:9092 +# compression.type: none +# statistics.interval.ms: "60000" +# queue.buffering.max.messages: "10" +# queue.buffering.max.kbytes: "1024" +# queue.buffering.max.ms: "1000" +# batch.size: "100" +# request.required.acks: "-1" +error_output: {} + # Additional logprep configurations # Note: The configuration keys 'logger', 'metrics', 'input' and 'output' will overwrite the # corresponding keys in these configurations as they will be merged into @@ -141,7 +163,7 @@ output: {} # pipeline: [] # - name: https://rule-server.de # -# See https://logprep.readthedocs.io/en/latest/user_manual/configuration/index.html#configuration-file-structure +# See https://logprep.readthedocs.io/en/latest/configuration/index.html#configuration-file-structure # for available configuration options. configurations: - name: logprep-config diff --git a/doc/source/configuration/index.rst b/doc/source/configuration/index.rst index c683d1b39..aa74789d3 100644 --- a/doc/source/configuration/index.rst +++ b/doc/source/configuration/index.rst @@ -8,7 +8,7 @@ Configuration :no-index: .. autoclass:: logprep.util.configuration.Configuration - :members: version, config_refresh_interval, process_count, timeout, logger, input, output, pipeline, metrics, profile_pipelines, print_auto_test_stack_trace + :members: version, config_refresh_interval, process_count, restart_count, timeout, logger, input, output, error_output, pipeline, metrics, profile_pipelines, print_auto_test_stack_trace, error_backlog_size :no-index: .. toctree:: diff --git a/doc/source/development/connector_how_to.rst b/doc/source/development/connector_how_to.rst index 2ac5eb97c..76b4f0fb6 100644 --- a/doc/source/development/connector_how_to.rst +++ b/doc/source/development/connector_how_to.rst @@ -4,7 +4,7 @@ Implementing a new Connector Connectors are used to fetch or store log messages. Input and ouput connectors work each independently, with the exception that an output connector -might call a callback function inside the input, to notify that the current batch was sucessfully +might call a callback function inside the input, to notify that the current batch was sucessfully processed. Only then the input would start collecting new inputs. Because of this independence, it is possible to receive messages from one system and to store them in another, i.e. reading from Kafka and writing to OpenSearch. @@ -40,7 +40,7 @@ An exception should be thrown if an error occurs on calling this function. These exceptions must inherit from the exception classes in :py:class:`~logprep.input.input.Input`. They should return a helpful message when calling `str(exception)`. Exceptions requiring Logprep to restart should inherit from `FatalInputError`. -Exceptions that inherit from `WarningInputError` will be logged, but they do not require any error +Exceptions that inherit from `WarningInputError` will be logged, but they do not require any error handling. .. _connector_output: @@ -62,12 +62,18 @@ They should return a helpful message when calling `str(exception)`. Analogous to the input, exceptions that require a restart of Logprep should inherit from `FatalOutputError`. Exceptions that inherit from `OutputWarning` will be logged, but they do not require any error handling. -:py:meth:`~logprep.output.output.Output.store_failed` -^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ -This method is being called if an error occurred during the processing of a log message. -The original log message, the partially processed log message and the error message are being passed to this method. -These will be stored separately from regular log messages for debugging and error handling. +.. _error_output: + +Error Output +------------ + +Error output is setup in :py:class:`~logprep.framework.pipeline_manager.PipelineManager`. The error +output connector is instantiated and setup only once during the initialization of the pipeline manager +together with :py:class:`~logprep.framework.pipeline_manager.OutputQueueListener`. +The listener is used to listen on the populated error queue and to send the log messages to the +:code:`store` method of the error output connector. +The error queue is given to the listener and to all pipelines instantiated by the pipeline manager. Factory diff --git a/doc/source/development/processor_how_to.rst b/doc/source/development/processor_how_to.rst index 656d61c9f..193ad5570 100644 --- a/doc/source/development/processor_how_to.rst +++ b/doc/source/development/processor_how_to.rst @@ -94,7 +94,7 @@ process This method is implemented in the :py:class:`~logprep.abc.processor.Processor` and is called for every log message. To process the event it invokes the processors `apply_rules` method. -If you want to do somthing to the event after all rules have been applied, then you could overwrite this method and implement your code after calling the `super().process(event)`. +If you want to do something to the event after all rules have been applied, then you could overwrite this method and implement your code after calling the `super().process(event)`. The log message is being passed as a dictionary and modified 'in place', meaning that modifications are being performed directly on the input event. .. code-block:: python @@ -112,11 +112,14 @@ The log message is being passed as a dictionary and modified 'in place', meaning Exceptions/Error Handling ~~~~~~~~~~~~~~~~~~~~~~~~~ -An exception should be thrown if an error occurs during the processing of a log message. -All exceptions are being logged and should return a helpful error message with `str(exception)`. -Exceptions derived from `ProcessorWarningError` have no impact on the operation of the processor. +An exception should not been thrown on processor level. Instead it should be added to +the :py:class:`~logprep.abc.processor.ProcessorResult` if an error occurs during the processing of a log message. +All exceptions are being logged in :py:class:`~logprep.framework.pipeline.Pipeline` and should provide a helpful +error message with `str(exception)`. You do not have to log the exception in the processor itself. +Exceptions derived from :py:class:`~logprep.processor.base.exceptions.ProcessingWarning` have no impact on the +operation of the processor. Other exceptions stop the processing of a log message. -However, the log message will be separately stored as failed (see :ref:`connector_output`, `store_failed``). +However, the log message will be separately stored as failed (see :ref:`error_output`). Metrics diff --git a/examples/compose/docker-compose.yml b/examples/compose/docker-compose.yml index 6cd312788..bf16308a1 100644 --- a/examples/compose/docker-compose.yml +++ b/examples/compose/docker-compose.yml @@ -1,5 +1,3 @@ -version: "3.9" - # The following command must be executed after each restart on linux or opensearch exits with an error # sudo sysctl -w vm.max_map_count=262144 diff --git a/examples/exampledata/config/file_input_pipeline.yml b/examples/exampledata/config/file_input_pipeline.yml new file mode 100644 index 000000000..d6d4de313 --- /dev/null +++ b/examples/exampledata/config/file_input_pipeline.yml @@ -0,0 +1,41 @@ +version: 2 +process_count: 4 +config_refresh_interval: 5 +profile_pipelines: false +restart_count: 3 +logger: + level: INFO + loggers: + uvicorn: + level: INFO + uvicorn.access: + level: INFO + uvicorn.error: + level: INFO + +metrics: + enabled: true + port: 8003 + uvicorn_config: + host: 0.0.0.0 + access_log: true + server_header: false + date_header: false + workers: 1 + ws: none + interface: asgi3 + backlog: 16384 + timeout_keep_alive: 65 +input: + file_input: + type: file_input + logfile_path: /tmp/logfiletest + start: begin + interval: 1 + watch_file: True +output: + dummy: + type: dummy_output +error_output: + console: + type: console_output diff --git a/examples/exampledata/config/grafana/dashboards/logprep-dashboard.json b/examples/exampledata/config/grafana/dashboards/logprep-dashboard.json index 6e978c600..fe6084347 100644 --- a/examples/exampledata/config/grafana/dashboards/logprep-dashboard.json +++ b/examples/exampledata/config/grafana/dashboards/logprep-dashboard.json @@ -18,7 +18,6 @@ "editable": true, "fiscalYearStartMonth": 0, "graphTooltip": 0, - "id": 2, "links": [ { "asDropdown": true, @@ -114,9 +113,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -196,9 +197,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -278,9 +281,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -360,9 +365,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -442,9 +449,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -524,9 +533,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -606,9 +617,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -676,9 +689,11 @@ "fields": "/^logprep$/", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -761,9 +776,11 @@ "fields": "/^config$/", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -845,9 +862,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -934,9 +953,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -1013,9 +1034,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -1096,9 +1119,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -1184,9 +1209,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1252,9 +1279,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1335,9 +1364,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -1402,9 +1433,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1422,7 +1455,6 @@ } ], "title": "Config Refresh Interval", - "transformations": [], "type": "stat" }, { @@ -1473,9 +1505,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1493,7 +1527,6 @@ } ], "title": "Config Reloads", - "transformations": [], "type": "stat" }, { @@ -1542,9 +1575,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1575,7 +1610,6 @@ "y": 7 }, "id": 131, - "links": [], "options": { "alertInstanceLabelFilter": "", "alertName": "", @@ -1655,9 +1689,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1736,9 +1772,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1817,9 +1855,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1890,9 +1930,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -1973,9 +2015,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -2001,7 +2045,7 @@ "type": "prometheus", "uid": "promz2394" }, - "description": "Number of objects that were collected by the garbage collector.", + "description": "Number of events in error queue", "fieldConfig": { "defaults": { "color": { @@ -2055,9 +2099,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -2067,7 +2113,7 @@ }, "editorMode": "code", "exemplar": false, - "expr": "sum(rate(python_gc_objects_collected_total[1m]))", + "expr": "sum(logprep_number_of_events_in_error_queue)", "hide": false, "instant": false, "legendFormat": "__auto", @@ -2075,7 +2121,7 @@ "refId": "A" } ], - "title": "collected/s", + "title": "error queue", "type": "stat" }, { @@ -2122,9 +2168,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "targets": [ { "datasource": { @@ -2223,9 +2271,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -2301,9 +2351,11 @@ "fields": "", "values": false }, - "textMode": "auto" + "showPercentChange": false, + "textMode": "auto", + "wideLayout": true }, - "pluginVersion": "10.1.4", + "pluginVersion": "10.4.2", "repeatDirection": "h", "targets": [ { @@ -2349,6 +2401,7 @@ "mode": "palette-classic" }, "custom": { + "axisBorderShow": false, "axisCenteredZero": false, "axisColorMode": "text", "axisLabel": "", @@ -2459,6 +2512,7 @@ "mode": "palette-classic" }, "custom": { + "axisBorderShow": false, "axisCenteredZero": false, "axisColorMode": "text", "axisLabel": "", @@ -2576,6 +2630,7 @@ "mode": "palette-classic" }, "custom": { + "axisBorderShow": false, "axisCenteredZero": false, "axisColorMode": "text", "axisLabel": "", @@ -4104,8 +4159,7 @@ } ], "refresh": "5s", - "schemaVersion": 38, - "style": "dark", + "schemaVersion": 39, "tags": [ "App" ], @@ -4122,4 +4176,4 @@ "uid": "Ijmjihx7z", "version": 1, "weekStart": "" -} +} \ No newline at end of file diff --git a/examples/exampledata/config/http_pipeline.yml b/examples/exampledata/config/http_pipeline.yml index 7eb3a7432..2bd2df9b3 100644 --- a/examples/exampledata/config/http_pipeline.yml +++ b/examples/exampledata/config/http_pipeline.yml @@ -53,7 +53,22 @@ output: kafka: type: confluentkafka_output topic: consumer - error_topic: errors + flush_timeout: 300 + send_timeout: 0 + kafka_config: + bootstrap.servers: 127.0.0.1:9092 + compression.type: none + statistics.interval.ms: "60000" + queue.buffering.max.messages: "100000000" + queue.buffering.max.kbytes: "1048576" + queue.buffering.max.ms: "10000" + batch.size: "1000000" + request.required.acks: "-1" + +error_output: + kafka: + type: confluentkafka_output + topic: errors flush_timeout: 300 send_timeout: 0 kafka_config: diff --git a/examples/exampledata/config/pipeline.yml b/examples/exampledata/config/pipeline.yml index ffed82e28..ce91f79b8 100644 --- a/examples/exampledata/config/pipeline.yml +++ b/examples/exampledata/config/pipeline.yml @@ -3,6 +3,7 @@ process_count: 2 timeout: 0.1 restart_count: 2 config_refresh_interval: 5 +error_backlog_size: 1500000 logger: level: INFO format: "%(asctime)-15s %(hostname)-5s %(name)-10s %(levelname)-8s: %(message)s" @@ -10,6 +11,11 @@ logger: loggers: "py.warnings": { "level": "ERROR" } "Runner": { "level": "DEBUG" } + "Processor": { "level": "ERROR" } + "Exporter": { "level": "ERROR" } + "uvicorn": { "level": "ERROR" } + "uvicorn.access": { "level": "ERROR" } + "OpenSearchOutput": { "level": "ERROR" } metrics: enabled: true port: 8001 @@ -115,11 +121,10 @@ output: hosts: - 127.0.0.1:9200 default_index: processed - error_index: errors + default_op_type: create message_backlog_size: 2500 timeout: 10000 flush_timeout: 60 - max_retries: 3 user: admin secret: admin desired_cluster_status: ["green", "yellow"] @@ -127,8 +132,23 @@ output: type: confluentkafka_output default: false topic: producer - error_topic: errors flush_timeout: 300 kafka_config: bootstrap.servers: 127.0.0.1:9092 statistics.interval.ms: "60000" + +error_output: + kafka: + type: confluentkafka_output + topic: errors + flush_timeout: 300 + send_timeout: 0 + kafka_config: + bootstrap.servers: 127.0.0.1:9092 + compression.type: none + statistics.interval.ms: "60000" + queue.buffering.max.messages: "10" + queue.buffering.max.kbytes: "1024" + queue.buffering.max.ms: "1000" + batch.size: "100" + request.required.acks: "-1" diff --git a/examples/k8s/values.yaml b/examples/k8s/values.yaml index 2753c4415..6abbfee9c 100644 --- a/examples/k8s/values.yaml +++ b/examples/k8s/values.yaml @@ -33,7 +33,6 @@ connector: output: type: confluentkafka_output topic: consumer - error_topic: errors flush_timeout: 300 send_timeout: 0 kafka_config: diff --git a/logprep/abc/component.py b/logprep/abc/component.py index adb3a72a7..317fd3912 100644 --- a/logprep/abc/component.py +++ b/logprep/abc/component.py @@ -55,10 +55,11 @@ def __attrs_post_init__(self): attribute.init_tracker() # __dict__ is added to support functools.cached_property - __slots__ = ["name", "_config", "__dict__"] + __slots__ = ["name", "_config", "pipeline_index", "__dict__"] # instance attributes name: str + pipeline_index: int _config: Config # class attributes @@ -71,9 +72,10 @@ def metric_labels(self) -> dict: """Labels for the metrics""" return {"component": self._config.type, "name": self.name, "description": "", "type": ""} - def __init__(self, name: str, configuration: "Component.Config"): + def __init__(self, name: str, configuration: "Component.Config", pipeline_index: int = None): self._config = configuration self.name = name + self.pipeline_index = pipeline_index @cached_property def metrics(self): @@ -100,7 +102,7 @@ def setup(self): """Set the component up.""" self._populate_cached_properties() if not "http" in self._config.type: - # HTTP input connector spins up an http server + # HTTP input connector spins up a http server # only on the first pipeline process # but this runs on all pipeline processes which leads to never # completing the setup phase diff --git a/logprep/abc/connector.py b/logprep/abc/connector.py index 28e03feec..92bb8a17f 100644 --- a/logprep/abc/connector.py +++ b/logprep/abc/connector.py @@ -21,14 +21,6 @@ class Metrics(Component.Metrics): ) """Number of successful events""" - number_of_failed_events: CounterMetric = field( - factory=lambda: CounterMetric( - description="Number of failed events", - name="number_of_failed_events", - ) - ) - """Number of failed events""" - processing_time_per_event: HistogramMetric = field( factory=lambda: HistogramMetric( description="Time in seconds that it took to store an event", diff --git a/logprep/abc/exceptions.py b/logprep/abc/exceptions.py index 593e84244..3e1dbb919 100644 --- a/logprep/abc/exceptions.py +++ b/logprep/abc/exceptions.py @@ -4,5 +4,9 @@ class LogprepException(Exception): """Base class for Logprep related exceptions.""" + def __init__(self, message: str, *args) -> None: + self.message = message + super().__init__(message, *args) + def __eq__(self, __value: object) -> bool: return type(self) is type(__value) and self.args == __value.args diff --git a/logprep/abc/input.py b/logprep/abc/input.py index e3fcd58e1..b63b6d820 100644 --- a/logprep/abc/input.py +++ b/logprep/abc/input.py @@ -7,9 +7,10 @@ import os import zlib from abc import abstractmethod +from copy import deepcopy from functools import partial from hmac import HMAC -from typing import TYPE_CHECKING, Optional, Tuple +from typing import Optional, Tuple from attrs import define, field, validators @@ -20,9 +21,6 @@ from logprep.util.time import UTC, TimeParser from logprep.util.validators import dict_structure_validator -if TYPE_CHECKING: # pragma: no cover - from logprep.abc.output import Output - class InputError(LogprepException): """Base class for Input related exceptions.""" @@ -36,8 +34,11 @@ class CriticalInputError(InputError): """A significant error occurred - log and don't process the event.""" def __init__(self, input_connector: "Input", message, raw_input): - self.raw_input = raw_input - super().__init__(input_connector, f"{message} -> {raw_input}") + super().__init__( + input_connector, f"{message} -> event was written to error output if configured" + ) + self.raw_input = deepcopy(raw_input) # is written to error output + self.message = message class CriticalInputParsingError(CriticalInputError): @@ -85,7 +86,7 @@ class HmacConfig: @define(kw_only=True) class TimeDeltaConfig: - """TimeDetla Configurations + """TimeDelta Configurations Works only if the preprocessor log_arrival_time_target_field is set.""" target_field: field(validator=[validators.instance_of(str), lambda _, __, x: bool(x)]) @@ -183,10 +184,6 @@ class Config(Connector.Config): }, ) - pipeline_index: int - output_connector: Optional["Output"] - __slots__ = ["pipeline_index", "output_connector"] - @property def _add_hmac(self): """Check and return if a hmac should be added or not.""" @@ -259,7 +256,7 @@ def _get_event(self, timeout: float) -> Tuple: """ @Metric.measure_time() - def get_next(self, timeout: float) -> Tuple[Optional[dict], Optional[str]]: + def get_next(self, timeout: float) -> dict | None: """Return the next document Parameters @@ -278,14 +275,13 @@ def get_next(self, timeout: float) -> Tuple[Optional[dict], Optional[str]]: After timeout (usually a fraction of seconds) if no input data was available by then. """ event, raw_event = self._get_event(timeout) - non_critical_error_msg = None if event is None: - return None, None + return self.metrics.number_of_processed_events += 1 if not isinstance(event, dict): raise CriticalInputError(self, "not a dict", event) if self._add_hmac: - event, non_critical_error_msg = self._add_hmac_to(event, raw_event) + event = self._add_hmac_to(event, raw_event) if self._add_version_info: self._add_version_information_to_event(event) if self._add_log_arrival_time_information: @@ -294,7 +290,7 @@ def get_next(self, timeout: float) -> Tuple[Optional[dict], Optional[str]]: self._add_arrival_timedelta_information_to_event(event) if self._add_env_enrichment: self._add_env_enrichment_to_event(event) - return event, non_critical_error_msg + return event def batch_finished_callback(self): """Can be called by output connectors after processing a batch of one or more records.""" @@ -356,10 +352,15 @@ def _add_hmac_to(self, event_dict, raw_event) -> Tuple[dict, str]: event_dict: dict The original event extended with a field that has the hmac and the corresponding target field, which was used to calculate the hmac. + + Raises + ------ + CriticalInputError + If the hmac could not be added to the event because the desired output field already + exists or cant't be found. """ hmac_options = self._config.preprocessing.get("hmac", {}) hmac_target_field_name = hmac_options.get("target") - non_critical_error_msg = None if raw_event is None: raw_event = self._encoder.encode(event_dict) @@ -370,21 +371,15 @@ def _add_hmac_to(self, event_dict, raw_event) -> Tuple[dict, str]: received_orig_message = get_dotted_field_value(event_dict, hmac_target_field_name) if received_orig_message is None: - hmac = "error" - received_orig_message = ( - f"".encode() - ) - non_critical_error_msg = ( - f"Couldn't find the hmac target " f"field '{hmac_target_field_name}'" - ) - else: - if isinstance(received_orig_message, str): - received_orig_message = received_orig_message.encode("utf-8") - hmac = HMAC( - key=hmac_options.get("key").encode(), - msg=received_orig_message, - digestmod=hashlib.sha256, - ).hexdigest() + error_message = f"Couldn't find the hmac target field '{hmac_target_field_name}'" + raise CriticalInputError(self, error_message, raw_event) + if isinstance(received_orig_message, str): + received_orig_message = received_orig_message.encode("utf-8") + hmac = HMAC( + key=hmac_options.get("key").encode(), + msg=received_orig_message, + digestmod=hashlib.sha256, + ).hexdigest() compressed = zlib.compress(received_orig_message, level=-1) hmac_output = {"hmac": hmac, "compressed_base64": base64.b64encode(compressed).decode()} add_was_successful = add_field_to( @@ -393,9 +388,11 @@ def _add_hmac_to(self, event_dict, raw_event) -> Tuple[dict, str]: hmac_output, ) if not add_was_successful: - non_critical_error_msg = ( + raise CriticalInputError( + self, f"Couldn't add the hmac to the input event as the desired " f"output field '{hmac_options.get('output_field')}' already " - f"exist." + f"exist.", + event_dict, ) - return event_dict, non_critical_error_msg + return event_dict diff --git a/logprep/abc/output.py b/logprep/abc/output.py index 1cc595572..b4bdba23a 100644 --- a/logprep/abc/output.py +++ b/logprep/abc/output.py @@ -3,13 +3,13 @@ """ from abc import abstractmethod -from typing import Optional +from copy import deepcopy +from typing import Any, Optional from attrs import define, field, validators from logprep.abc.connector import Connector from logprep.abc.exceptions import LogprepException -from logprep.abc.input import Input class OutputError(LogprepException): @@ -31,10 +31,12 @@ def __init__(self, output: "Output", message: str) -> None: class CriticalOutputError(OutputError): """A significant error occurred - log and don't process the event.""" - def __init__(self, output, message, raw_input): - if raw_input: - output.store_failed(str(self), raw_input, {}) - super().__init__(output, f"{message} for event: {raw_input}") + __match_args__ = ("raw_input",) + + def __init__(self, output: "Output", message: str, raw_input: Any) -> None: + super().__init__(output, f"{message} -> event was written to error output if configured") + self.raw_input = deepcopy(raw_input) + self.message = message class FatalOutputError(OutputError): @@ -53,10 +55,6 @@ class Config(Connector.Config): But this output can be called as output for extra_data. """ - __slots__ = {"input_connector"} - - input_connector: Optional[Input] - @property def default(self): """returns the default parameter""" @@ -90,9 +88,5 @@ def store(self, document: dict) -> Optional[bool]: def store_custom(self, document: dict, target: str): """Store additional data in a custom location inside the output destination.""" - @abstractmethod - def store_failed(self, error_message: str, document_received: dict, document_processed: dict): - """Store an event when an error occurred during the processing.""" - def _write_backlog(self): """Write the backlog to the output destination.""" diff --git a/logprep/abc/processor.py b/logprep/abc/processor.py index 4f3ef6b12..1bdd6ac60 100644 --- a/logprep/abc/processor.py +++ b/logprep/abc/processor.py @@ -158,7 +158,7 @@ def __init__(self, name: str, configuration: "Processor.Config"): if os.environ.get("LOGPREP_BYPASS_RULE_TREE"): self._bypass_rule_tree = True self._rules = self.rules - logger.info("Bypassing rule tree for processor %s", self.name) + logger.debug("Bypassing rule tree for processor %s", self.name) @property def _specific_rules(self): @@ -271,8 +271,8 @@ def _apply_rules_wrapper(self, event: dict, rule: "Rule"): except ProcessingCriticalError as error: self.result.errors.append(error) # is needed to prevent wrapping it in itself event.clear() - except Exception as error: - self.result.errors.append(ProcessingCriticalError(str(error), rule, event)) + except Exception as error: # pylint: disable=broad-except + self.result.errors.append(ProcessingCriticalError(str(error), rule)) event.clear() if not hasattr(rule, "delete_source_fields"): return diff --git a/logprep/connector/confluent_kafka/input.py b/logprep/connector/confluent_kafka/input.py index 1b2bfc6c2..53ce16f96 100644 --- a/logprep/connector/confluent_kafka/input.py +++ b/logprep/connector/confluent_kafka/input.py @@ -29,6 +29,7 @@ """ # pylint: enable=line-too-long import logging +import os from functools import cached_property, partial from socket import getfqdn from types import MappingProxyType @@ -43,8 +44,10 @@ OFFSET_STORED, Consumer, KafkaException, + Message, TopicPartition, ) +from confluent_kafka.admin import AdminClient from logprep.abc.connector import Connector from logprep.abc.input import ( @@ -242,13 +245,13 @@ class Config(Input.Config): """ - _last_valid_records: dict + _last_valid_record: Message - __slots__ = ["_last_valid_records"] + __slots__ = ["_last_valid_record"] def __init__(self, name: str, configuration: "Connector.Config") -> None: super().__init__(name, configuration) - self._last_valid_records = {} + self._last_valid_record = None @property def _kafka_config(self) -> dict: @@ -268,8 +271,25 @@ def _kafka_config(self) -> dict: "error_cb": self._error_callback, } DEFAULTS.update({"client.id": getfqdn()}) + DEFAULTS.update( + { + "group.instance.id": f"{getfqdn().strip('.')}-Pipeline{self.pipeline_index}-pid{os.getpid()}" + } + ) return DEFAULTS | self._config.kafka_config | injected_config + @cached_property + def _admin(self) -> AdminClient: + """configures and returns the admin client + + Returns + ------- + AdminClient + confluent_kafka admin client object + """ + admin_config = {"bootstrap.servers": self._config.kafka_config["bootstrap.servers"]} + return AdminClient(admin_config) + @cached_property def _consumer(self) -> Consumer: """configures and returns the consumer @@ -279,14 +299,7 @@ def _consumer(self) -> Consumer: Consumer confluent_kafka consumer object """ - consumer = Consumer(self._kafka_config) - consumer.subscribe( - [self._config.topic], - on_assign=self._assign_callback, - on_revoke=self._revoke_callback, - on_lost=self._lost_callback, - ) - return consumer + return Consumer(self._kafka_config) def _error_callback(self, error: KafkaException) -> None: """Callback for generic/global error events, these errors are typically @@ -406,7 +419,7 @@ def _get_raw_event(self, timeout: float) -> bytearray: raise CriticalInputError( self, "A confluent-kafka record contains an error code", str(kafka_error) ) - self._last_valid_records[message.partition()] = message + self._last_valid_record = message labels = {"description": f"topic: {self._config.topic} - partition: {message.partition()}"} self.metrics.current_offsets.add_with_labels(message.offset() + 1, labels) return message.value() @@ -455,17 +468,15 @@ def _enable_auto_commit(self) -> bool: return self._config.kafka_config.get("enable.auto.commit") == "true" def batch_finished_callback(self) -> None: - """Store offsets for each kafka partition in `self._last_valid_records`. - Should be called by output connectors if they are finished processing - a batch of records. + """Store offsets for last message referenced by `self._last_valid_records`. + Should be called after delivering the current message to the output or error queue. """ if self._enable_auto_offset_store: return - for message in self._last_valid_records.values(): - try: - self._consumer.store_offsets(message=message) - except KafkaException as error: - raise InputWarning(self, f"{error}, {message}") from error + try: + self._consumer.store_offsets(message=self._last_valid_record) + except KafkaException as error: + raise InputWarning(self, f"{error}, {self._last_valid_record}") from error def _assign_callback(self, consumer, topic_partitions): for topic_partition in topic_partitions: @@ -492,7 +503,6 @@ def _revoke_callback(self, consumer, topic_partitions): topic_partition.topic, topic_partition.partition, ) - self.output_connector._write_backlog() self.batch_finished_callback() def _lost_callback(self, consumer, topic_partitions): @@ -520,7 +530,7 @@ def health(self) -> bool: """ try: - metadata = self._consumer.list_topics(timeout=self._config.health_timeout) + metadata = self._admin.list_topics(timeout=self._config.health_timeout) if not self._config.topic in metadata.topics: logger.error("Topic '%s' does not exit", self._config.topic) return False @@ -533,6 +543,12 @@ def health(self) -> bool: def setup(self) -> None: """Set the component up.""" try: + self._consumer.subscribe( + [self._config.topic], + on_assign=self._assign_callback, + on_revoke=self._revoke_callback, + on_lost=self._lost_callback, + ) super().setup() except KafkaException as error: raise FatalInputError(self, f"Could not setup kafka consumer: {error}") from error diff --git a/logprep/connector/confluent_kafka/output.py b/logprep/connector/confluent_kafka/output.py index 1550b4b02..2c02a323a 100644 --- a/logprep/connector/confluent_kafka/output.py +++ b/logprep/connector/confluent_kafka/output.py @@ -14,7 +14,6 @@ my_confluent_kafka_output: type: confluentkafka_output topic: my_default_topic - error_topic: my_error_topic flush_timeout: 0.2 send_timeout: 0 kafka_config: @@ -24,9 +23,7 @@ queue.buffering.max.ms: 0.5 """ -import json import logging -from datetime import datetime from functools import cached_property, partial from socket import getfqdn from types import MappingProxyType @@ -34,6 +31,7 @@ from attrs import define, field, validators from confluent_kafka import KafkaException, Producer +from confluent_kafka.admin import AdminClient from logprep.abc.output import CriticalOutputError, FatalOutputError, Output from logprep.metrics.metrics import GaugeMetric, Metric @@ -148,8 +146,6 @@ class Config(Output.Config): topic: str = field(validator=validators.instance_of(str)) """The topic into which the processed events should be written to.""" - error_topic: str = field(validator=validators.instance_of(str)) - """The topic into which the failed events should be written to.""" flush_timeout: float = field( validator=validators.instance_of(float), converter=float, default=0 ) @@ -206,6 +202,18 @@ def _kafka_config(self) -> dict: DEFAULTS.update({"client.id": getfqdn()}) return DEFAULTS | self._config.kafka_config | injected_config + @cached_property + def _admin(self) -> AdminClient: + """configures and returns the admin client + + Returns + ------- + AdminClient + confluent_kafka admin client object + """ + admin_config = {"bootstrap.servers": self._config.kafka_config["bootstrap.servers"]} + return AdminClient(admin_config) + @cached_property def _producer(self) -> Producer: return Producer(self._kafka_config) @@ -274,8 +282,6 @@ def store(self, document: dict) -> Optional[bool]: configured input """ self.store_custom(document, self._config.topic) - if self.input_connector: - self.input_connector.batch_finished_callback() @Metric.measure_time() def store_custom(self, document: dict, target: str) -> None: @@ -295,48 +301,15 @@ def store_custom(self, document: dict, target: str) -> None: """ try: self._producer.produce(target, value=self._encoder.encode(document)) + logger.debug("Produced message %s to topic %s", str(document), target) self._producer.poll(self._config.send_timeout) self.metrics.number_of_processed_events += 1 except BufferError: # block program until buffer is empty or timeout is reached self._producer.flush(timeout=self._config.flush_timeout) - except BaseException as error: - raise CriticalOutputError( - self, f"Error storing output document -> {error}", document - ) from error - - @Metric.measure_time() - def store_failed( - self, error_message: str, document_received: dict, document_processed: dict - ) -> None: - """Write errors into error topic for documents that failed processing. - - Parameters - ---------- - error_message : str - Error message to write into Kafka document. - document_received : dict - Document as it was before processing. - document_processed : dict - Document after processing until an error occurred. - - """ - self.metrics.number_of_failed_events += 1 - value = { - "error": error_message, - "original": document_received, - "processed": document_processed, - "timestamp": str(datetime.now()), - } - try: - self._producer.produce( - self._config.error_topic, - value=json.dumps(value, separators=(",", ":")).encode("utf-8"), - ) - self._producer.poll(self._config.send_timeout) - except BufferError: - # block program until buffer is empty - self._producer.flush(timeout=self._config.flush_timeout) + logger.debug("Buffer full, flushing") + except Exception as error: + raise CriticalOutputError(self, str(error), document) from error def shut_down(self) -> None: """ensures that all messages are flushed. According to @@ -359,7 +332,7 @@ def shut_down(self) -> None: def health(self) -> bool: """Check the health of kafka producer.""" try: - metadata = self._producer.list_topics(timeout=self._config.health_timeout) + metadata = self._admin.list_topics(timeout=self._config.health_timeout) if not self._config.topic in metadata.topics: logger.error("Topic '%s' does not exit", self._config.topic) return False diff --git a/logprep/connector/console/output.py b/logprep/connector/console/output.py index fe824ae06..544624d55 100644 --- a/logprep/connector/console/output.py +++ b/logprep/connector/console/output.py @@ -27,13 +27,7 @@ class ConsoleOutput(Output): def store(self, document: dict): pprint(document) self.metrics.number_of_processed_events += 1 - if self.input_connector: - self.input_connector.batch_finished_callback() def store_custom(self, document: dict, target: str): self.metrics.number_of_processed_events += 1 pprint(document, stream=getattr(sys, target)) - - def store_failed(self, error_message: str, document_received: dict, document_processed: dict): - self.metrics.number_of_failed_events += 1 - pprint(f"{error_message}: {document_received}, {document_processed}", stream=sys.stderr) diff --git a/logprep/connector/dummy/output.py b/logprep/connector/dummy/output.py index 743be5217..017301e29 100644 --- a/logprep/connector/dummy/output.py +++ b/logprep/connector/dummy/output.py @@ -85,19 +85,10 @@ def store(self, document: dict): raise Exception(exception) # pylint: disable=broad-exception-raised self.events.append(document) self.metrics.number_of_processed_events += 1 - if self.input_connector: - self.input_connector.batch_finished_callback() def store_custom(self, document: dict, target: str): """Store additional data in a custom location inside the output destination.""" self.store(document) - def store_failed(self, error_message: str, document_received: dict, document_processed: dict): - """Store an event when an error occurred during the processing.""" - if self._config.do_nothing: - return - self.metrics.number_of_failed_events += 1 - self.failed_events.append((error_message, document_received, document_processed)) - def shut_down(self): self.shut_down_called_count += 1 diff --git a/logprep/connector/http/input.py b/logprep/connector/http/input.py index 87b4bd86e..57436d58b 100644 --- a/logprep/connector/http/input.py +++ b/logprep/connector/http/input.py @@ -439,10 +439,8 @@ def setup(self): """ super().setup() - if not hasattr(self, "pipeline_index"): - raise FatalInputError( - self, "Necessary instance attribute `pipeline_index` could not be found." - ) + if self.pipeline_index is None: + raise FatalInputError(self, "Necessary instance attribute `pipeline_index` is not set.") # Start HTTP Input only when in first process if self.pipeline_index != 1: return diff --git a/logprep/connector/http/output.py b/logprep/connector/http/output.py index 4ba65a8cf..043301adb 100644 --- a/logprep/connector/http/output.py +++ b/logprep/connector/http/output.py @@ -36,9 +36,6 @@ This connector does not verify the SSL Context, which could lead to exposing sensitive data. -.. warning:: - The :code:`store_failed` method only counts the number of failed events and does not send them - to a dead letter queue. """ import json @@ -62,6 +59,14 @@ class HttpOutput(Output): class Metrics(Output.Metrics): """Tracks statistics about this connector""" + number_of_failed_events: CounterMetric = field( + factory=lambda: CounterMetric( + description="Number of failed events", + name="number_of_failed_events", + ) + ) + """Number of failed events""" + number_of_http_requests: CounterMetric = field( factory=lambda: CounterMetric( description="Requests total", @@ -164,9 +169,6 @@ def store(self, document: tuple[str, dict | list[dict]] | dict) -> None: target = self._config.target_url self.store_custom(document, target) - def store_failed(self, error_message, document_received, document_processed) -> None: - self.metrics.number_of_failed_events += 1 - def store_custom(self, document: dict | tuple | list, target: str) -> None: """Send a post request with given data to the specified endpoint""" if isinstance(document, (tuple, list)): @@ -201,8 +203,6 @@ def store_custom(self, document: dict | tuple | list, target: str) -> None: response.raise_for_status() self.metrics.number_of_processed_events += document_count self.metrics.number_of_http_requests += 1 - if self.input_connector is not None: - self.input_connector.batch_finished_callback() except requests.RequestException as error: logger.error("Failed to send event: %s", str(error)) logger.debug("Failed event: %s", document) diff --git a/logprep/connector/jsonl/output.py b/logprep/connector/jsonl/output.py index fa3e9eb9e..9a0fe3a4f 100644 --- a/logprep/connector/jsonl/output.py +++ b/logprep/connector/jsonl/output.py @@ -19,7 +19,6 @@ """ import json -from logging import Logger from attrs import define, field, validators @@ -45,7 +44,6 @@ class Config(Output.Config): output_file = field(validator=validators.instance_of(str)) output_file_custom = field(validator=validators.instance_of(str), default="") - output_file_error = field(validator=validators.instance_of(str), default="") last_timeout: float events: list @@ -67,8 +65,6 @@ def setup(self): open(self._config.output_file, "a+", encoding="utf8").close() if self._config.output_file_custom: open(self._config.output_file_custom, "a+", encoding="utf8").close() - if self._config.output_file_error: - open(self._config.output_file_error, "a+", encoding="utf8").close() @staticmethod def _write_json(filepath: str, line: dict): @@ -80,8 +76,6 @@ def store(self, document: dict): self.events.append(document) JsonlOutput._write_json(self._config.output_file, document) self.metrics.number_of_processed_events += 1 - if self.input_connector: - self.input_connector.batch_finished_callback() def store_custom(self, document: dict, target: str): document = {target: document} @@ -90,17 +84,3 @@ def store_custom(self, document: dict, target: str): if self._config.output_file_custom: JsonlOutput._write_json(self._config.output_file_custom, document) self.metrics.number_of_processed_events += 1 - - def store_failed(self, error_message: str, document_received: dict, document_processed: dict): - self.metrics.number_of_failed_events += 1 - self.failed_events.append((error_message, document_received, document_processed)) - - if self._config.output_file_error: - JsonlOutput._write_json( - self._config.output_file_error, - { - "error_message": error_message, - "document_received": document_received, - "document_processed": document_processed, - }, - ) diff --git a/logprep/connector/opensearch/output.py b/logprep/connector/opensearch/output.py index dd65b242f..4dcf9c2f8 100644 --- a/logprep/connector/opensearch/output.py +++ b/logprep/connector/opensearch/output.py @@ -30,24 +30,18 @@ ca_cert: /path/to/cert.crt """ -import json import logging -import random -import re import ssl -import time from functools import cached_property -from typing import List, Optional, Tuple, Union +from typing import List, Optional import opensearchpy as search from attrs import define, field, validators from opensearchpy import OpenSearchException, helpers from opensearchpy.serializer import JSONSerializer -from logprep.abc.output import FatalOutputError, Output +from logprep.abc.output import CriticalOutputError, Output from logprep.metrics.metrics import Metric -from logprep.util.helper import get_dict_size_in_byte -from logprep.util.time import TimeParser logger = logging.getLogger("OpenSearchOutput") @@ -101,24 +95,10 @@ class Config(Output.Config): """Default index to write to if no index was set in the document or the document could not be indexed. The document will be transformed into a string to prevent rejections by the default index.""" - error_index: str = field(validator=validators.instance_of(str)) - """Index to write documents to that could not be processed.""" message_backlog_size: int = field(validator=validators.instance_of(int)) """Amount of documents to store before sending them.""" - maximum_message_size_mb: Optional[Union[float, int]] = field( - validator=validators.optional(validators.instance_of((float, int))), - converter=(lambda x: x * 10**6 if x else None), - default=None, - ) - """(Optional) Maximum estimated size of a document in MB before discarding it if it causes - an error.""" timeout: int = field(validator=validators.instance_of(int), default=500) """(Optional) Timeout for the connection (default is 500ms).""" - max_retries: int = field(validator=validators.instance_of(int), default=0) - """(Optional) Maximum number of retries for documents rejected with code 429 (default is 0). - Increases backoff time by 2 seconds per try, but never exceeds 600 seconds. When using - parallel_bulk in the opensearch connector then the backoff time starts with 1 second. With - each consecutive retry 500 to 1000 ms will be added to the delay, chosen randomly """ user: Optional[str] = field(validator=validators.instance_of(str), default="") """(Optional) User used for authentication.""" secret: Optional[str] = field(validator=validators.instance_of(str), default="") @@ -128,10 +108,6 @@ class Config(Output.Config): flush_timeout: Optional[int] = field(validator=validators.instance_of(int), default=60) """(Optional) Timeout after :code:`message_backlog` is flushed if :code:`message_backlog_size` is not reached.""" - - parallel_bulk: bool = field(default=True, validator=validators.instance_of(bool)) - """Configure if all events in the backlog should be send, in parallel, via multiple threads - to Opensearch. (Default: :code:`True`)""" thread_count: int = field( default=4, validator=[validators.instance_of(int), validators.gt(1)] ) @@ -144,16 +120,32 @@ class Config(Output.Config): default=500, validator=[validators.instance_of(int), validators.gt(1)] ) """Chunk size to use for bulk requests.""" + max_chunk_bytes: int = field( + default=100 * 1024 * 1024, validator=[validators.instance_of(int), validators.gt(1)] + ) + """Max chunk size to use for bulk requests. The default is 100MB.""" + max_retries: int = field( + default=3, validator=[validators.instance_of(int), validators.gt(0)] + ) + """Max retries for all requests. Default is 3.""" desired_cluster_status: list = field( default=["green"], validator=validators.instance_of(list) ) """Desired cluster status for health check as list of strings. Default is ["green"]""" + default_op_type: str = field( + default="index", + validator=[validators.instance_of(str), validators.in_(["create", "index"])], + ) + """Default op_type for indexing documents. Default is 'index', + Consider using 'create' for data streams or to prevent overwriting existing documents.""" - __slots__ = ["_message_backlog", "_size_error_pattern"] + __slots__ = ["_message_backlog", "_failed"] - _message_backlog: List + _failed: List + """Temporary list of failed messages.""" - _size_error_pattern: re.Pattern[str] + _message_backlog: List + """List of messages to be sent to Opensearch.""" @cached_property def ssl_context(self) -> ssl.SSLContext: @@ -198,26 +190,25 @@ def http_auth(self) -> tuple: @cached_property def _search_context(self): + """Returns the opensearch client.""" return search.OpenSearch( self._config.hosts, scheme=self.schema, http_auth=self.http_auth, ssl_context=self.ssl_context, + verify_certs=True, # default is True, but we want to be explicit timeout=self._config.timeout, serializer=MSGPECSerializer(self), + max_retries=self._config.max_retries, + pool_maxsize=10, + # default for connection pooling is 10 see: + # https://github.com/opensearch-project/opensearch-py/blob/main/guides/connection_classes.md ) - @cached_property - def _replace_pattern(self): - return re.compile(r"%{\S+?}") - def __init__(self, name: str, configuration: "OpensearchOutput.Config"): super().__init__(name, configuration) self._message_backlog = [] - self._size_error_pattern = re.compile( - r".*coordinating_operation_bytes=(?P\d+), " - r"max_coordinating_and_primary_bytes=(?P\d+).*" - ) + self._failed = [] def setup(self): super().setup() @@ -236,34 +227,19 @@ def describe(self) -> str: base_description = Output.describe(self) return f"{base_description} - Opensearch Output: {self._config.hosts}" - def store(self, document: dict): - """Store a document in the index. + def store(self, document: dict) -> None: + """Store a document in the index defined in the document or to the default index. Parameters ---------- document : dict Document to store. - - Returns - ------- - Returns True to inform the pipeline to call the batch_finished_callback method in the - configured input """ - if document.get("_index") is None: - document = self._build_failed_index_document(document, "Missing index in document") - - self._add_dates(document) - self.metrics.number_of_processed_events += 1 - self._message_backlog.append(document) - self._write_to_search_context() + self.store_custom(document, document.get("_index", self._config.default_index)) - def store_custom(self, document: dict, target: str): + def store_custom(self, document: dict, target: str) -> None: """Store document into backlog to be written into Opensearch with the target index. - - Only add to backlog instead of writing the batch and calling batch_finished_callback, - since store_custom can be called before the event has been fully processed. - Setting the offset or committing before fully processing an event can lead to data loss if - Logprep terminates. + The target index is determined per document by parameter :code:`target`. Parameters ---------- @@ -271,74 +247,18 @@ def store_custom(self, document: dict, target: str): Document to be stored into the target index. target : str Index to store the document in. - Raises - ------ - CriticalOutputError - Raises if any error except a BufferError occurs while writing into opensearch. - """ document["_index"] = target - self._add_dates(document) + document["_op_type"] = document.get("_op_type", self._config.default_op_type) self.metrics.number_of_processed_events += 1 self._message_backlog.append(document) - - def store_failed(self, error_message: str, document_received: dict, document_processed: dict): - """Write errors into error topic for documents that failed processing. - - Parameters - ---------- - error_message : str - Error message to write into Kafka document. - document_received : dict - Document as it was before processing. - document_processed : dict - Document after processing until an error occurred. - - """ - self.metrics.number_of_failed_events += 1 - error_document = { - "error": error_message, - "original": document_received, - "processed": document_processed, - "@timestamp": TimeParser.now().isoformat(), - "_index": self._config.error_index, - } - self._add_dates(error_document) - self._message_backlog.append(error_document) self._write_to_search_context() - def _build_failed_index_document(self, message_document: dict, reason: str): - document = { - "reason": reason, - "@timestamp": TimeParser.now().isoformat(), - "_index": self._config.default_index, - } - try: - document["message"] = json.dumps(message_document) - except TypeError: - document["message"] = str(message_document) - return document - - def _add_dates(self, document): - date_format_matches = self._replace_pattern.findall(document["_index"]) - if date_format_matches: - now = TimeParser.now() - for date_format_match in date_format_matches: - formatted_date = now.strftime(date_format_match[2:-1]) - document["_index"] = re.sub(date_format_match, formatted_date, document["_index"]) - def _write_to_search_context(self): """Writes documents from a buffer into Opensearch indices. Writes documents in a bulk if the document buffer limit has been reached. - This reduces connections to Opensearch. - The target index is determined per document by the value of the meta field '_index'. - A configured default index is used if '_index' hasn't been set. - - Returns - ------- - Returns True to inform the pipeline to call the batch_finished_callback method in the - configured input + This reduces connections to Opensearch and improves performance. """ if len(self._message_backlog) >= self._config.message_backlog_size: self._write_backlog() @@ -347,213 +267,40 @@ def _write_to_search_context(self): def _write_backlog(self): if not self._message_backlog: return - - self._bulk( - self._search_context, - self._message_backlog, - max_retries=self._config.max_retries, - chunk_size=len(self._message_backlog), - ) - if self.input_connector and hasattr(self.input_connector, "batch_finished_callback"): - self.input_connector.batch_finished_callback() - self._message_backlog.clear() - - def _bulk(self, client, actions, *args, **kwargs): + logger.debug("Flushing %d documents to Opensearch", len(self._message_backlog)) try: - if self._config.parallel_bulk: - self._parallel_bulk(client, actions, *args, **kwargs) - return - helpers.bulk(client, actions, *args, **kwargs) - except search.SerializationError as error: - self._handle_serialization_error(error) - except search.ConnectionError as error: - self._handle_connection_error(error) - except helpers.BulkIndexError as error: - self._handle_bulk_index_error(error) - except search.exceptions.TransportError as error: - self._handle_transport_error(error) - - def _parallel_bulk(self, client, actions, *args, **kwargs): - bulk_delays = 1 - for _ in range(self._config.max_retries + 1): - try: - for success, item in helpers.parallel_bulk( - client, - actions=actions, - chunk_size=self._config.chunk_size, - queue_size=self._config.queue_size, - raise_on_error=True, - raise_on_exception=True, - ): - if not success: - result = item[list(item.keys())[0]] - if "error" in result: - raise result.get("error") - break - except search.ConnectionError as error: - raise error - except search.exceptions.TransportError as error: - if self._message_exceeds_max_size_error(error): - raise error - time.sleep(bulk_delays) - bulk_delays += random.randint(500, 1000) / 1000 - else: - raise FatalOutputError( - self, "Opensearch too many requests, all parallel bulk retries failed" - ) - - def _handle_serialization_error(self, error: search.SerializationError): - """Handle serialization error for opensearch bulk indexing. - - If at least one document in a chunk can't be serialized, no events will be sent. - The chunk size is thus set to be the same size as the message backlog size. - Therefore, it won't result in duplicates once the data is resent. - - Parameters - ---------- - error : SerializationError - SerializationError for the error message. - - Raises - ------ - FatalOutputError - This causes a pipeline rebuild and gives an appropriate error log message. - - """ - raise FatalOutputError(self, f"{error.args[1]} in document {error.args[0]}") - - def _handle_connection_error(self, error: search.ConnectionError): - """Handle connection error for opensearch bulk indexing. - - No documents will be sent if there is no connection to begin with. - Therefore, it won't result in duplicates once the the data is resent. - If the connection is lost during indexing, duplicate documents could be sent. - - Parameters - ---------- - error : ConnectionError - ConnectionError for the error message. - - Raises - ------ - FatalOutputError - This causes a pipeline rebuild and gives an appropriate error log message. - - """ - raise FatalOutputError(self, error.error) - - def _handle_bulk_index_error(self, error: helpers.BulkIndexError): - """Handle bulk indexing error for opensearch bulk indexing. - - Documents that could not be sent to opensearch due to index errors are collected and - sent into an error index that should always accept all documents. - This can lead to a rebuild of the pipeline if this causes another exception. - - Parameters - ---------- - error : BulkIndexError - BulkIndexError to collect IndexErrors from. - - """ - error_documents = [] - for bulk_error in error.errors: - _, error_info = bulk_error.popitem() - data = error_info.get("data") if "data" in error_info else None - error_type = error_info.get("error").get("type") - error_reason = error_info.get("error").get("reason") - reason = f"{error_type}: {error_reason}" - error_document = self._build_failed_index_document(data, reason) - self._add_dates(error_document) - error_documents.append(error_document) - self._bulk(self._search_context, error_documents) - - def _handle_transport_error(self, error: search.exceptions.TransportError): - """Handle transport error for opensearch bulk indexing. - - Discard messages that exceed the maximum size if they caused an error. - - Parameters - ---------- - error : TransportError - TransportError for the error message. - - """ - if self._config.maximum_message_size_mb is None: - raise FatalOutputError(self, error.error) - - if self._message_exceeds_max_size_error(error): - ( - messages_under_size_limit, - messages_over_size_limit, - ) = self._split_message_backlog_by_size_limit() - - if len(messages_over_size_limit) == 0: - raise FatalOutputError(self, error.error) - - error_documents = self._build_messages_for_large_error_documents( - messages_over_size_limit - ) - self._message_backlog = error_documents + messages_under_size_limit self._bulk(self._search_context, self._message_backlog) - else: - raise FatalOutputError(self, error.error) - - def _message_exceeds_max_size_error(self, error): - if error.status_code == 429: - if error.error == "circuit_breaking_exception": - return True - - if error.error == "rejected_execution_exception": - reason = error.info.get("error", {}).get("reason", "") - match = self._size_error_pattern.match(reason) - if match and int(match.group("size")) >= int(match.group("max_size")): - return True - return False - - def _build_messages_for_large_error_documents( - self, messages_over_size_limit: List[Tuple[dict, int]] - ) -> List[dict]: - """Build error message for messages that were larger than the allowed size limit. - - Only a snipped of the message is stored in the error document, since the original message - was too large to be written in the first place. - - Parameters - ---------- - messages_over_size_limit : List[Tuple[dict, int]] - Messages that were too large with their corresponding sizes in byte. - + except CriticalOutputError as error: + raise error from error + except Exception as error: # pylint: disable=broad-except + logger.error("Failed to index documents: %s", error) + raise CriticalOutputError(self, str(error), self._message_backlog) from error + finally: + self._message_backlog.clear() + self._failed.clear() + + def _bulk(self, client, actions): + """Bulk index documents into Opensearch. + Uses the parallel_bulk function from the opensearchpy library. """ - error_documents = [] - for message, size in messages_over_size_limit: - error_message = ( - f"Discarded message that is larger than the allowed size limit " - f"({size / 10 ** 6} MB/{self._config.maximum_message_size_mb} MB)" - ) - logger.warning(error_message) - - error_document = { - "processed_snipped": f'{self._encoder.encode(message).decode("utf-8")[:1000]} ...', - "error": error_message, - "@timestamp": TimeParser.now().isoformat(), - "_index": self._config.error_index, - } - self._add_dates(error_document) - error_documents.append(error_document) - return error_documents - - def _split_message_backlog_by_size_limit(self): - messages_under_size_limit = [] - messages_over_size_limit = [] - total_size = 0 - for message in self._message_backlog: - message_size = get_dict_size_in_byte(message) - if message_size < self._config.maximum_message_size_mb: - messages_under_size_limit.append(message) - total_size += message_size - else: - messages_over_size_limit.append((message, message_size)) - return messages_under_size_limit, messages_over_size_limit + kwargs = { + "max_chunk_bytes": self._config.max_chunk_bytes, + "chunk_size": self._config.chunk_size, + "queue_size": self._config.queue_size, + "raise_on_error": False, + "raise_on_exception": False, + } + failed = self._failed + for index, result in enumerate(helpers.parallel_bulk(client, actions, **kwargs)): + success, item = result + if success: + continue + error_result = item.get(self._config.default_op_type) + error = error_result.get("error", "Failed to index document") + data = actions[index] + failed.append({"errors": error, "event": data}) + if failed: + raise CriticalOutputError(self, "failed to index", failed) def health(self) -> bool: """Check the health of the component.""" diff --git a/logprep/connector/s3/output.py b/logprep/connector/s3/output.py index 82a24514a..830c54bee 100644 --- a/logprep/connector/s3/output.py +++ b/logprep/connector/s3/output.py @@ -252,31 +252,6 @@ def store_custom(self, document: dict, target: str) -> None: self.metrics.number_of_processed_events += 1 self._add_to_backlog(document, target) - def store_failed( - self, error_message: str, document_received: dict, document_processed: dict - ) -> None: - """Write errors into s3 bucket using error prefix for documents that failed processing. - - Parameters - ---------- - error_message : str - Error message to write into document. - document_received : dict - Document as it was before processing. - document_processed : dict - Document after processing until an error occurred. - - """ - self.metrics.number_of_failed_events += 1 - error_document = { - "error": error_message, - "original": document_received, - "processed": document_processed, - "@timestamp": TimeParser.now().isoformat(), - } - self._add_to_backlog(error_document, self._config.error_prefix) - self._write_to_s3_resource() - def _add_dates(self, prefix: str) -> str: date_format_matches = self._replace_pattern.findall(prefix) if date_format_matches: @@ -317,9 +292,6 @@ def _write_backlog(self) -> None: if not self._config.call_input_callback: return - if self.input_connector and hasattr(self.input_connector, "batch_finished_callback"): - self.input_connector.batch_finished_callback() - @_handle_s3_error def _write_document_batch(self, document_batch: dict, identifier: str) -> None: logger.debug('Writing "%s" to s3 bucket "%s"', identifier, self._config.bucket) diff --git a/logprep/framework/pipeline.py b/logprep/framework/pipeline.py index 74eadad80..04bd44a9e 100644 --- a/logprep/framework/pipeline.py +++ b/logprep/framework/pipeline.py @@ -5,7 +5,6 @@ """ -import copy import itertools import logging import logging.handlers @@ -18,14 +17,13 @@ from functools import cached_property, partial from importlib.metadata import version from multiprocessing import Value, current_process -from typing import Any, Generator, List, Tuple +from typing import Any, List, Tuple import attrs from logprep.abc.component import Component from logprep.abc.input import ( CriticalInputError, - CriticalInputParsingError, FatalInputError, Input, InputWarning, @@ -39,7 +37,7 @@ ) from logprep.abc.processor import Processor, ProcessorResult from logprep.factory import Factory -from logprep.metrics.metrics import HistogramMetric, Metric +from logprep.metrics.metrics import CounterMetric, HistogramMetric, Metric from logprep.processor.base.exceptions import ProcessingError, ProcessingWarning from logprep.util.configuration import Configuration from logprep.util.pipeline_profiler import PipelineProfiler @@ -64,22 +62,30 @@ class PipelineResult: The result object """ + __match_args__ = ("event", "errors") + results: List[ProcessorResult] = attrs.field( validator=[ attrs.validators.instance_of(list), attrs.validators.deep_iterable( member_validator=attrs.validators.instance_of(ProcessorResult) ), - ] + ], + init=False, ) """List of ProcessorResults. Is populated in __attrs_post_init__""" event: dict = attrs.field(validator=attrs.validators.instance_of(dict)) """The event that was processed""" - event_received: dict = attrs.field( - validator=attrs.validators.instance_of(dict), converter=copy.deepcopy + + pipeline: list[Processor] = attrs.field( + validator=[ + attrs.validators.deep_iterable( + member_validator=attrs.validators.instance_of(Processor), + iterable_validator=attrs.validators.instance_of(list), + ), + attrs.validators.min_len(1), + ] ) - """The event that was received""" - pipeline: list[Processor] """The pipeline that processed the event""" @cached_property @@ -113,17 +119,12 @@ def _inner(self: "Pipeline") -> Any: self.stop() except (OutputWarning, InputWarning) as error: self.logger.warning(str(error)) - except CriticalOutputError as error: + except (CriticalInputError, CriticalOutputError) as error: + self.enqueue_error(error) self.logger.error(str(error)) except (FatalOutputError, FatalInputError) as error: self.logger.error(str(error)) self.stop() - except CriticalInputError as error: - if (raw_input := error.raw_input) and self._output: # pylint: disable=protected-access - for _, output in self._output.items(): # pylint: disable=protected-access - if output.default: - output.store_failed(str(self), raw_input, {}) - self.logger.error(str(error)) return None return _inner @@ -139,6 +140,14 @@ class Pipeline: class Metrics(Component.Metrics): """Tracks statistics about a pipeline""" + number_of_failed_events: CounterMetric = attrs.field( + factory=lambda: CounterMetric( + description="Number of failed events", + name="number_of_failed_events", + ) + ) + """Number of failed events""" + processing_time_per_event: HistogramMetric = attrs.field( factory=lambda: HistogramMetric( description="Time in seconds that it took to process an event", @@ -150,7 +159,7 @@ class Metrics(Component.Metrics): _logprep_config: Configuration """ the logprep configuration dict """ - _continue_iterating: Value + _continue_iterating: Any """ a flag to signal if iterating continues """ pipeline_index: int @@ -212,7 +221,13 @@ def _input(self) -> Input: ) return Factory.create(input_connector_config) - def __init__(self, config: Configuration, pipeline_index: int = None) -> None: + def __init__( + self, + config: Configuration, + pipeline_index: int | None = None, + error_queue: multiprocessing.queues.Queue | None = None, + ) -> None: + self.error_queue = error_queue self.logger = logging.getLogger("Pipeline") self.logger.name = f"Pipeline{pipeline_index}" self._logprep_config = config @@ -226,9 +241,6 @@ def __init__(self, config: Configuration, pipeline_index: int = None) -> None: def _setup(self): self.logger.debug("Creating connectors") for _, output in self._output.items(): - output.input_connector = self._input - if output.default: - self._input.output_connector = output output.setup() self.logger.debug( f"Created connectors -> input: '{self._input.describe()}'," @@ -262,21 +274,20 @@ def run(self) -> None: # pylint: disable=method-hidden self._shut_down() @_handle_pipeline_error - def process_pipeline(self) -> PipelineResult: + def process_pipeline(self) -> PipelineResult | None: """Retrieve next event, process event with full pipeline and store or return results""" Component.run_pending_tasks() - - event = self._get_event() - result = None + event = self._input.get_next(self._timeout) if not event: - return None, None + return + result = None if self._pipeline: result: PipelineResult = self.process_event(event) if result.warnings: self.logger.warning(",".join((str(warning) for warning in result.warnings))) if result.errors: self.logger.error(",".join((str(error) for error in result.errors))) - self._store_failed_event(result.errors, result.event_received, event) + self.enqueue_error(result) return if self._output: if self._pipeline: @@ -285,6 +296,8 @@ def process_pipeline(self) -> PipelineResult: self._store_extra_data(itertools.chain(*result_data)) if event: self._store_event(event) + if self._input: + self._input.batch_finished_callback() return result def _store_event(self, event: dict) -> None: @@ -293,33 +306,13 @@ def _store_event(self, event: dict) -> None: output.store(event) self.logger.debug(f"Stored output in {output_name}") - def _store_failed_event(self, error, event_received, event): - for _, output in self._output.items(): - if output.default: - output.store_failed(str(error), event_received, event) - - def _get_event(self) -> dict: - try: - event, non_critical_error_msg = self._input.get_next(self._timeout) - if non_critical_error_msg and self._output: - self._store_failed_event(non_critical_error_msg, event, None) - return event - except CriticalInputParsingError as error: - input_data = error.raw_input - if isinstance(input_data, bytes): - input_data = input_data.decode("utf8") - self._store_failed_event(error, {"invalid_json": input_data}, "") - @Metric.measure_time() def process_event(self, event: dict): """process all processors for one event""" - result = PipelineResult( - results=[], - event_received=event, + return PipelineResult( event=event, pipeline=self._pipeline, ) - return result def _store_extra_data(self, result_data: List | itertools.chain) -> None: self.logger.debug("Storing extra data") @@ -352,7 +345,7 @@ def stop(self) -> None: with self._continue_iterating.get_lock(): self._continue_iterating.value = False - def get_health_functions(self) -> Tuple[bool]: + def get_health_functions(self) -> Tuple: """Return health function of components""" output_health_functions = [] if self._output: @@ -364,3 +357,66 @@ def get_health_functions(self) -> Tuple[bool]: output_health_functions, ) ) + + def enqueue_error( + self, item: PipelineResult | CriticalInputError | CriticalOutputError + ) -> None: + """Enqueues an error to the error queue or logs a warning if + no error queue is defined.""" + if not self.error_queue: + self.logger.warning("No error queue defined, event was dropped") + if self._input: + self._input.batch_finished_callback() + return + self.logger.debug(f"Enqueuing error item: {item}") + match item: + case CriticalOutputError(): + event = self._get_output_error_event(item) + case PipelineResult(input_event, errors): + self.metrics.number_of_failed_events += 1 + event = { + "event": str(input_event), + "errors": ", ".join((str(error.message) for error in errors)), + } + case CriticalInputError(): + self.metrics.number_of_failed_events += 1 + event = {"event": str(item.raw_input), "errors": str(item.message)} + case list(): + event = [{"event": str(i), "errors": "Unknown error"} for i in item] + case _: + event = {"event": str(item), "errors": "Unknown error"} + try: + if isinstance(event, list): + for i in event: + self.logger.debug(f"Enqueuing error item: {i}") + self.error_queue.put(i, timeout=0.1) + self.logger.debug("Enqueued error item") + else: + self.logger.debug(f"Enqueuing error item: {event}") + self.error_queue.put(event, timeout=0.1) + self.logger.debug("Enqueued error item") + except Exception as error: # pylint: disable=broad-except + self.logger.error( + f"[Error Event] Couldn't enqueue error item due to: {error} | Item: '{event}'" + ) + if self._input: + self._input.batch_finished_callback() + + def _get_output_error_event(self, item: CriticalOutputError) -> dict | list: + match item: + case CriticalOutputError([{"errors": _, "event": _}, *_]): + event = [ + {"event": str(i["event"]), "errors": str(i["errors"])} for i in item.raw_input + ] + self.metrics.number_of_failed_events += len(event) + return event + case CriticalOutputError({"errors": error, "event": event}): + self.metrics.number_of_failed_events += 1 + return {"event": str(event), "errors": str(error)} + case CriticalOutputError(raw_input) if isinstance(raw_input, (list, tuple)): + event = [{"event": str(i), "errors": str(item.message)} for i in raw_input] + self.metrics.number_of_failed_events += len(event) + return event + case _: + self.metrics.number_of_failed_events += 1 + return {"event": str(item.raw_input), "errors": str(item.message)} diff --git a/logprep/framework/pipeline_manager.py b/logprep/framework/pipeline_manager.py index d6b89e88f..a0a3034be 100644 --- a/logprep/framework/pipeline_manager.py +++ b/logprep/framework/pipeline_manager.py @@ -1,23 +1,26 @@ """This module contains functionality to manage pipelines via multi-processing.""" # pylint: disable=logging-fstring-interpolation - import logging import logging.handlers import multiprocessing import multiprocessing.managers import multiprocessing.queues import random +import sys import time +from typing import Any -from attr import define, field +from attr import define, field, validators from logprep.abc.component import Component from logprep.connector.http.input import HttpInput +from logprep.factory import Factory from logprep.framework.pipeline import Pipeline from logprep.metrics.exporter import PrometheusExporter from logprep.metrics.metrics import CounterMetric from logprep.util.configuration import Configuration +from logprep.util.defaults import DEFAULT_MESSAGE_BACKLOG_SIZE, EXITCODES from logprep.util.logging import LogprepMPQueueListener, logqueue logger = logging.getLogger("Manager") @@ -53,6 +56,109 @@ def put(self, obj, block=True, timeout=None, batch_size=1): super().put(obj, block=block, timeout=timeout) +@define() +class OutputQueueListener: + """This forks a process and handles all items from the given queue into + the specified callable. It uses a sentinel object to stop the process.""" + + queue: multiprocessing.queues.Queue = field( + validator=validators.instance_of(multiprocessing.queues.Queue) + ) + """The queue to listen to.""" + + target: str = field(validator=validators.instance_of(str)) + """The method name of the component which will be used to handle the items from the queue.""" + + config: dict = field(validator=validators.instance_of(dict)) + """The configuration of the component used in this listener instance.""" + + sentinel: Any = field(default=None, init=False) + """The sentinel object to stop the process. This has to implement identity comparison.""" + + _process: multiprocessing.Process = field(init=False) + """The process that is forked to listen to the queue.""" + + def __attrs_post_init__(self): + self._process = multiprocessing.Process(target=self._listen, daemon=True) + + def start(self): + """Start the listener.""" + logger.debug("Starting listener with target: %s", self.target) + self._process.start() + + def get_output_instance(self): + """ + Returns an instance of an output. + + This method creates an instance of an output using the Factory and configures it with the setup method. + If an error occurs during setup, it logs an error message, puts a sentinel value into the queue, and raises + the error. The method waits until the queue is empty before returning the component instance. The '1' added to + the queue and the waiting for the queue being empty again is to ensure that the process are synchronized. + + Raises: + ------- + SystemExit: If an error occurs during the setup of the output component. + + Returns: + ------- + The configured output instance. + """ + output = Factory.create(self.config) + try: + output.setup() + self.queue.put(1) + except SystemExit as error: + logger.error("Error output not reachable. Exiting...") + self.queue.put(self.sentinel) + raise error from error + # wait for setup method in pipeline manager to receive the message + while not self.queue.empty(): + logger.debug("Waiting for receiver to be ready") + return output + + def _listen(self): + component = self.get_output_instance() + target = getattr(component, self.target) + while 1: + item = self.queue.get() + if item == 1: + continue + logger.debug("Got item from queue: %s", item) + if item is self.sentinel: + logger.debug("Got sentinel. Stopping listener.") + break + try: + target(item) + except Exception as error: # pylint: disable=broad-except + logger.error( + f"[Error Event] Couldn't enqueue error item due to: {error} | Item: '{item}'" + ) + self._drain_queue(target) + component.shut_down() + + def _drain_queue(self, target): + while not self.queue.empty(): + item = self.queue.get() + if item == 1: # first queue item, added for process synchronization + continue + if item is self.sentinel: + logger.debug("Got another sentinel") + continue + try: + target(item) + except Exception as error: # pylint: disable=broad-except + logger.error( + f"[Error Event] Couldn't enqueue error item due to: {error} | Item: '{item}'" + ) + self.queue.close() # close queue after draining to prevent message loss + + def stop(self): + """Stop the listener.""" + self.queue.put(self.sentinel) + self._process.join() + logger.debug("Stopped listener.") + + class PipelineManager: """Manage pipelines via multi-processing.""" @@ -85,16 +191,18 @@ class Metrics(Component.Metrics): """Number of failed pipelines""" def __init__(self, configuration: Configuration): - self.restart_count = 0 - self.restart_timeout_ms = random.randint(100, 1000) + self.restart_count: int = 0 + self.restart_timeout_ms: int = random.randint(100, 1000) self.metrics = self.Metrics(labels={"component": "manager"}) self.loghandler: LogprepMPQueueListener = None - self._error_queue: multiprocessing.Queue | None = None + self.error_queue: multiprocessing.Queue | None = None + self._error_listener: OutputQueueListener | None = None self._configuration: Configuration = configuration self._pipelines: list[multiprocessing.Process] = [] self.prometheus_exporter: PrometheusExporter | None = None if multiprocessing.current_process().name == "MainProcess": self._setup_logging() + self._setup_error_queue() self._setup_prometheus_exporter() self._set_http_input_queue() @@ -104,6 +212,23 @@ def _setup_prometheus_exporter(self): self.prometheus_exporter = PrometheusExporter(prometheus_config) self.prometheus_exporter.prepare_multiprocessing() + def _setup_error_queue(self): + if not self._configuration.error_output: + return + self.error_queue = ThrottlingQueue( + multiprocessing.get_context(), self._configuration.error_backlog_size + ) + self._error_listener = OutputQueueListener( + self.error_queue, + "store", + self._configuration.error_output, + ) + self._error_listener.start() + # wait for the error listener to be ready before starting the pipelines + if self.error_queue.get(block=True) is self._error_listener.sentinel: + self.stop() + sys.exit(EXITCODES.ERROR_OUTPUT_NOT_REACHABLE.value) + def _setup_logging(self): console_logger = logging.getLogger("console") if console_logger.handlers: @@ -121,7 +246,9 @@ def _set_http_input_queue(self): is_http_input = input_config.get("type") == "http_input" if not is_http_input and HttpInput.messages is not None: return - message_backlog_size = input_config.get("message_backlog_size", 15000) + message_backlog_size = input_config.get( + "message_backlog_size", DEFAULT_MESSAGE_BACKLOG_SIZE + ) HttpInput.messages = ThrottlingQueue(multiprocessing.get_context(), message_backlog_size) def set_count(self, count: int): @@ -188,6 +315,8 @@ def _wait_to_restart(self): def stop(self): """Stop processing any pipelines by reducing the pipeline count to zero.""" self.set_count(0) + if self._error_listener: + self._error_listener.stop() if self.prometheus_exporter: self.prometheus_exporter.server.shut_down() self.prometheus_exporter.cleanup_prometheus_multiprocess_dir() @@ -200,18 +329,29 @@ def start(self): self.set_count(self._configuration.process_count) def restart(self): - """Restarts all pipelines""" + """Restarts the manager.""" self.stop() self.start() def reload(self): + """Restarts all pipelines.""" self.set_count(0) self.set_count(self._configuration.process_count) def _create_pipeline(self, index) -> multiprocessing.Process: - pipeline = Pipeline(pipeline_index=index, config=self._configuration) + pipeline = Pipeline( + pipeline_index=index, + config=self._configuration, + error_queue=self.error_queue, + ) if pipeline.pipeline_index == 1 and self.prometheus_exporter: - self.prometheus_exporter.update_healthchecks(pipeline.get_health_functions()) + if self._configuration.error_output and self._error_listener: + error_output_healthcheck = self._error_listener.get_output_instance().health + self.prometheus_exporter.update_healthchecks( + [error_output_healthcheck, *pipeline.get_health_functions()] + ) + else: + self.prometheus_exporter.update_healthchecks(pipeline.get_health_functions()) process = multiprocessing.Process( target=pipeline.run, daemon=True, name=f"Pipeline-{index}" ) diff --git a/logprep/processor/base/exceptions.py b/logprep/processor/base/exceptions.py index c0b31f165..9f020b3c6 100644 --- a/logprep/processor/base/exceptions.py +++ b/logprep/processor/base/exceptions.py @@ -60,12 +60,11 @@ def __init__(self, message: str, rule: "Rule"): class ProcessingCriticalError(ProcessingError): """A critical error occurred - stop processing of this event""" - def __init__(self, message: str, rule: "Rule", event: dict): - message = ( - f"{message} -> event was send to error output and further processing stopped" - f", {rule.id=}, {rule.description=}, {event=}" - ) - super().__init__(f"{self.__class__.__name__}: {message}", rule) + def __init__(self, message: str, rule: "Rule"): + message = f"'{message}' -> rule.id: '{rule.id}'" + full_message = f"{message} -> event was send to error output and further processing stopped" + super().__init__(f"{self.__class__.__name__}: {full_message}", rule) + self.message = message class ProcessingWarning(Warning): diff --git a/logprep/processor/generic_resolver/processor.py b/logprep/processor/generic_resolver/processor.py index aaa1f2dad..12196668b 100644 --- a/logprep/processor/generic_resolver/processor.py +++ b/logprep/processor/generic_resolver/processor.py @@ -41,8 +41,8 @@ class GenericResolverError(ProcessingCriticalError): """Base class for GenericResolver related exceptions.""" - def __init__(self, name: str, message: str, rule: GenericResolverRule, event: dict): - super().__init__(f"{name}: {message}", rule=rule, event=event) + def __init__(self, name: str, message: str, rule: GenericResolverRule): + super().__init__(f"{name}: {message}", rule=rule) class GenericResolver(FieldManager): @@ -82,7 +82,6 @@ def _apply_rules(self, event, rule): self.name, "Mapping group is missing in mapping file pattern!", rule=rule, - event=event, ) dest_val = replacements.get(mapping) if dest_val: @@ -151,12 +150,10 @@ def ensure_rules_from_file(self, rule): f'\'{rule.resolve_from_file["path"]}\'' f" must be a dictionary with string values!", rule=rule, - event=None, ) except FileNotFoundError as error: raise GenericResolverError( self.name, f'Additions file \'{rule.resolve_from_file["path"]}' f"' not found!", rule=rule, - event=None, ) from error diff --git a/logprep/runner.py b/logprep/runner.py index 0448c8eda..634b6b2dd 100644 --- a/logprep/runner.py +++ b/logprep/runner.py @@ -58,6 +58,14 @@ class Runner: class Metrics(Component.Metrics): """Metrics for the Logprep Runner.""" + number_of_events_in_error_queue: GaugeMetric = field( + factory=lambda: GaugeMetric( + description="Current number of events in error queue", + name="number_of_events_in_error_queue", + ) + ) + """Current size of the error queue.""" + version_info: GaugeMetric = field( factory=lambda: GaugeMetric( description="Logprep version information", @@ -166,6 +174,8 @@ def _iterate(self): self.exit_code = EXITCODES.PIPELINE_ERROR.value self._logger.error("Restart count exceeded. Exiting.") sys.exit(self.exit_code) + if self._manager.error_queue is not None: + self.metrics.number_of_events_in_error_queue += self._manager.error_queue.qsize() self._manager.restart_failed_pipeline() def reload_configuration(self): diff --git a/logprep/util/configuration.py b/logprep/util/configuration.py index 3dc5a6a90..451258f38 100644 --- a/logprep/util/configuration.py +++ b/logprep/util/configuration.py @@ -45,7 +45,6 @@ kafka: type: confluentkafka_output topic: producer - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: @@ -184,7 +183,6 @@ kafka: type: confluentkafka_output topic: producer - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: @@ -225,6 +223,7 @@ from logprep.util.defaults import ( DEFAULT_CONFIG_LOCATION, DEFAULT_LOG_CONFIG, + DEFAULT_MESSAGE_BACKLOG_SIZE, DEFAULT_RESTART_COUNT, ENV_NAME_LOGPREP_CREDENTIALS_FILE, ) @@ -365,10 +364,10 @@ class LoggerConfig: format: str = field(default="", validator=[validators.instance_of(str)], eq=False) """The format of the log message as supported by the :code:`LogprepFormatter`. Defaults to :code:`"%(asctime)-15s %(name)-10s %(levelname)-8s: %(message)s"`. - + .. autoclass:: logprep.util.logging.LogprepFormatter :no-index: - + """ datefmt: str = field(default="", validator=[validators.instance_of(str)], eq=False) """The date format of the log message. Defaults to :code:`"%Y-%m-%d %H:%M:%S"`.""" @@ -527,6 +526,14 @@ class Configuration: Output connector configuration. Defaults to :code:`{}`. For detailed configurations see :ref:`output`. """ + error_output: dict = field(validator=validators.instance_of(dict), factory=dict, eq=False) + """ + Error output connector configuration. Defaults to :code:`{}`. + This is optional. If no error output is configured, logprep will not handle events that + could not be processed by the pipeline, not parsed correctly by input connectors or not + stored correctly by output connectors. + For detailed configurations see :ref:`output`. + """ pipeline: list[dict] = field(validator=validators.instance_of(list), factory=list, eq=False) """ Pipeline configuration. Defaults to :code:`[]`. @@ -538,9 +545,9 @@ class Configuration: converter=lambda x: MetricsConfig(**x) if isinstance(x, dict) else x, eq=False, ) - """Metrics configuration. Defaults to + """Metrics configuration. Defaults to :code:`{"enabled": False, "port": 8000, "uvicorn_config": {}}`. - + The key :code:`uvicorn_config` can be configured with any uvicorn config parameters. For further information see the `uvicorn documentation `_. @@ -568,6 +575,10 @@ class Configuration: """Start the profiler to profile the pipeline. Defaults to :code:`False`.""" print_auto_test_stack_trace: bool = field(default=False, eq=False) """Print stack trace when auto test fails. Defaults to :code:`False`.""" + error_backlog_size: int = field( + validator=validators.instance_of(int), default=DEFAULT_MESSAGE_BACKLOG_SIZE, eq=False + ) + """Size of the error backlog. Defaults to :code:`15000`.""" _getter: Getter = field( validator=validators.instance_of(Getter), @@ -826,6 +837,12 @@ def _verify(self): Factory.create({output_name: output_config}) except Exception as error: # pylint: disable=broad-except errors.append(error) + if self.error_output: + for output_name, output_config in self.error_output.items(): + try: + Factory.create({output_name: output_config}) + except Exception as error: # pylint: disable=broad-except + errors.append(error) for processor_config in self.pipeline: try: processor = Factory.create(deepcopy(processor_config)) diff --git a/logprep/util/defaults.py b/logprep/util/defaults.py index 0d87c687b..f84cdc414 100644 --- a/logprep/util/defaults.py +++ b/logprep/util/defaults.py @@ -14,8 +14,11 @@ class EXITCODES(Enum): """An error in the configuration.""" PIPELINE_ERROR = 3 """An error during pipeline processing.""" + ERROR_OUTPUT_NOT_REACHABLE = 4 + """The configured error output is not reachable.""" +DEFAULT_MESSAGE_BACKLOG_SIZE = 15000 DEFAULT_RESTART_COUNT = 5 DEFAULT_CONFIG_LOCATION = "file:///etc/logprep/pipeline.yml" DEFAULT_LOG_FORMAT = "%(asctime)-15s %(process)-6s %(name)-10s %(levelname)-8s: %(message)s" diff --git a/logprep/util/helper.py b/logprep/util/helper.py index c51ab2786..e8e4fec45 100644 --- a/logprep/util/helper.py +++ b/logprep/util/helper.py @@ -304,19 +304,6 @@ def get_source_fields_dict(event, rule): return source_field_dict -def get_dict_size_in_byte(dictionary: dict) -> int: - """returns the size of a nested dictionary in bytes""" - size = sys.getsizeof(dictionary) - if isinstance(dictionary, dict): - keys_size = sum(map(get_dict_size_in_byte, dictionary.keys())) - values_size = sum(map(get_dict_size_in_byte, dictionary.values())) - return size + keys_size + values_size - if isinstance(dictionary, list): - elements_size = sum(map(get_dict_size_in_byte, dictionary)) - return size + elements_size - return size - - def get_versions_string(config: "Configuration" = None) -> str: """ Prints the version and exists. If a configuration was found then it's version diff --git a/pyproject.toml b/pyproject.toml index 09b735733..85d38a036 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -94,7 +94,7 @@ dependencies = [ "click", "pandas", "tabulate", - "falcon==3.1.3", + "falcon>=3.1.3", "uvloop", "httptools", "rstr", diff --git a/tests/acceptance/test_error_output.py b/tests/acceptance/test_error_output.py new file mode 100644 index 000000000..7ae1a085b --- /dev/null +++ b/tests/acceptance/test_error_output.py @@ -0,0 +1,106 @@ +#!/usr/bin/env python3 +# pylint: disable=not-an-iterable +# pylint: disable=missing-docstring + +import json +import tempfile +import time +import uuid +from logging import DEBUG, basicConfig, getLogger +from pathlib import Path + +import pytest + +from logprep.util.configuration import Configuration +from tests.acceptance.util import start_logprep, stop_logprep, wait_for_output + +basicConfig(level=DEBUG, format="%(asctime)-15s %(name)-5s %(levelname)-8s: %(message)s") +logger = getLogger("Logprep-Test") + + +@pytest.fixture(name="config") +def get_config(): + config_dict = { + "process_count": 1, + "timeout": 0.1, + "profile_pipelines": False, + "pipeline": [], + "input": { + "jsonl_input": { + "type": "jsonl_input", + "documents_path": tempfile.mktemp(suffix=".input.jsonl"), + "preprocessing": { + "hmac": { + "target": "doesnotexist.never.ever", + "key": "thisisasecureandrandomkey", + "output_field": "Full_event", + }, + }, + } + }, + "output": { + "jsonl_output": { + "type": "dummy_output", + } + }, + "error_output": { + "jsonl": { + "type": "jsonl_output", + "output_file": tempfile.mktemp(suffix=".error.jsonl"), + } + }, + } + + return Configuration(**config_dict) + + +def teardown_function(): + Path("generated_config.yml").unlink(missing_ok=True) + stop_logprep() + + +def test_error_output_for_critical_input_error_with_missing_hmac_target_field( + tmp_path, config: Configuration +): + input_path = Path(config.input["jsonl_input"]["documents_path"]) + error_output_path = Path(config.error_output["jsonl"]["output_file"]) + content = str(uuid.uuid4()) + event = {"something": content} + input_path.write_text(json.dumps(event), encoding="utf8") + config.output.update({"kafka": {"type": "dummy_output", "default": False}}) + config_path = tmp_path / "generated_config.yml" + config_path.write_text(config.as_yaml(), encoding="utf-8") + proc = start_logprep(config_path) + output = proc.stdout.readline().decode("utf8") + # exclude error from forbidden_outputs as the config file path has the word error in it + wait_for_output( + proc, "Couldn't find the hmac target field", forbidden_outputs=["Invalid", "Exception"] + ) + start = time.time() + while not error_output_path.read_text(encoding="utf8"): + output = proc.stdout.readline().decode("utf8") + assert "not JSON serializable" not in output + if time.time() - start > 10: + assert False, "Timeout reached" + error_content = error_output_path.read_text(encoding="utf8") + assert content in error_content + + +def test_error_output_errors_are_logged_if_error_output_has_an_error( + tmp_path, config: Configuration +): + config.input = { + "dummy": {"type": "dummy_input", "documents": [{"something": "yeah"}, "Exception"]} + } + config.error_output = {"dummy": {"type": "dummy_output", "exceptions": ["Exception"]}} + config.error_backlog_size = 1 + config.output.update({"kafka": {"type": "dummy_output", "default": False}}) + config_path = tmp_path / "generated_config.yml" + config_path.write_text(config.as_yaml(), encoding="utf-8") + proc = start_logprep(config_path) + wait_for_output( + proc, + ".*\[Error Event\] Couldn't enqueue error item due to:.*", + test_timeout=30, + forbidden_outputs=[], + ) diff --git a/tests/acceptance/test_multiple_outputs.py b/tests/acceptance/test_multiple_outputs.py index 942757b2f..dafdd1cd7 100644 --- a/tests/acceptance/test_multiple_outputs.py +++ b/tests/acceptance/test_multiple_outputs.py @@ -1,5 +1,6 @@ # pylint: disable=missing-docstring # pylint: disable=line-too-long +import tempfile import time from pathlib import Path @@ -17,67 +18,85 @@ def wait_for_interval(interval): @pytest.fixture(name="config") def get_config(): - return Configuration( - **{ - "version": "1", - "logger": {"level": "DEBUG"}, - "process_count": 1, - "timeout": 0.1, - "profile_pipelines": False, - "pipeline": [ - { - "dissector": { - "type": "dissector", - "specific_rules": ["tests/testdata/acceptance/dissector/rules/specific"], - "generic_rules": ["tests/testdata/acceptance/dissector/rules/generic"], - } - }, - { - "selective_extractor": { - "type": "selective_extractor", - "specific_rules": [ - "tests/testdata/acceptance/selective_extractor/rules/specific" - ], - "generic_rules": [ - "tests/testdata/acceptance/selective_extractor/rules/generic" - ], - } - }, - { - "pseudonymizer": { - "type": "pseudonymizer", - "pubkey_analyst": "tests/testdata/acceptance/pseudonymizer/example_analyst_pub.pem", - "pubkey_depseudo": "tests/testdata/acceptance/pseudonymizer/example_depseudo_pub.pem", - "hash_salt": "a_secret_tasty_ingredient", - "outputs": [{"jsonl": "pseudonyms"}], - "specific_rules": [ - "tests/testdata/acceptance/pseudonymizer/rules_static/specific" - ], - "generic_rules": [ - "tests/testdata/acceptance/pseudonymizer/rules_static/generic" - ], - "regex_mapping": "tests/testdata/acceptance/pseudonymizer/rules_static/regex_mapping.yml", - "max_cached_pseudonyms": 1000000, - } - }, - { - "pre_detector": { - "type": "pre_detector", - "outputs": [{"jsonl": "pre_detector_topic"}], - "generic_rules": ["tests/testdata/acceptance/pre_detector/rules/generic"], - "specific_rules": ["tests/testdata/acceptance/pre_detector/rules/specific"], - "tree_config": "tests/testdata/acceptance/pre_detector/tree_config.json", - } - }, - ], - "input": { - "jsonl": { - "type": "jsonl_input", - "documents_path": "tests/testdata/input_logdata/kafka_raw_event_for_pre_detector.jsonl", + config = { + "version": "1", + "logger": {"level": "DEBUG"}, + "process_count": 1, + "timeout": 0.1, + "profile_pipelines": False, + "restart_count": -1, + "pipeline": [ + { + "dissector": { + "type": "dissector", + "specific_rules": ["tests/testdata/acceptance/dissector/rules/specific"], + "generic_rules": ["tests/testdata/acceptance/dissector/rules/generic"], } }, - } - ) + { + "selective_extractor": { + "type": "selective_extractor", + "specific_rules": [ + "tests/testdata/acceptance/selective_extractor/rules/specific" + ], + "generic_rules": [ + "tests/testdata/acceptance/selective_extractor/rules/generic" + ], + } + }, + { + "pseudonymizer": { + "type": "pseudonymizer", + "pubkey_analyst": "tests/testdata/acceptance/pseudonymizer/example_analyst_pub.pem", + "pubkey_depseudo": "tests/testdata/acceptance/pseudonymizer/example_depseudo_pub.pem", + "hash_salt": "a_secret_tasty_ingredient", + "outputs": [{"second_output": "pseudonyms"}], + "specific_rules": [ + "tests/testdata/acceptance/pseudonymizer/rules_static/specific" + ], + "generic_rules": [ + "tests/testdata/acceptance/pseudonymizer/rules_static/generic" + ], + "regex_mapping": "tests/testdata/acceptance/pseudonymizer/rules_static/regex_mapping.yml", + "max_cached_pseudonyms": 1000000, + } + }, + { + "pre_detector": { + "type": "pre_detector", + "outputs": [{"jsonl": "pre_detector_topic"}], + "generic_rules": ["tests/testdata/acceptance/pre_detector/rules/generic"], + "specific_rules": ["tests/testdata/acceptance/pre_detector/rules/specific"], + "tree_config": "tests/testdata/acceptance/pre_detector/tree_config.json", + } + }, + ], + "input": { + "jsonl": { + "type": "jsonl_input", + "documents_path": "tests/testdata/input_logdata/selective_extractor_events.jsonl", + } + }, + "output": { + "jsonl": { + "type": "jsonl_output", + "output_file": tempfile.mkstemp(suffix="output1.jsonl")[1], + "output_file_custom": tempfile.mkstemp(suffix="custom1.jsonl")[1], + }, + "second_output": { + "type": "jsonl_output", + "output_file": tempfile.mkstemp(suffix="output2.jsonl")[1], + "output_file_custom": tempfile.mkstemp(suffix="custom2.jsonl")[1], + }, + }, + "error_output": { + "jsonl": { + "type": "jsonl_output", + "output_file": tempfile.mkstemp(suffix="error.jsonl")[1], + } + }, + } + return Configuration(**config) def setup_function(): @@ -89,41 +108,22 @@ def teardown_function(): def test_full_pipeline_run_with_two_outputs(tmp_path: Path, config: Configuration): - output_path1 = tmp_path / "output1.jsonl" - output_path_custom1 = tmp_path / "output_custom1.jsonl" - output_path_error1 = tmp_path / "output_error1.jsonl" - output_path2 = tmp_path / "output2.jsonl" - output_path_custom2 = tmp_path / "output_custom2.jsonl" - output_path_error2 = tmp_path / "output_error2.jsonl" - config.input["jsonl"][ - "documents_path" - ] = "tests/testdata/input_logdata/selective_extractor_events.jsonl" - config.output = { - "jsonl": { - "type": "jsonl_output", - "output_file": f"{str(output_path1)}", - "output_file_custom": f"{str(output_path_custom1)}", - "output_file_error": f"{str(output_path_error1)}", - }, - "second_output": { - "type": "jsonl_output", - "output_file": f"{str(output_path2)}", - "output_file_custom": f"{str(output_path_custom2)}", - "output_file_error": f"{str(output_path_error2)}", - }, - } + output_path1 = Path(config.output["jsonl"]["output_file"]) + output_path_custom1 = Path(config.output["jsonl"]["output_file_custom"]) + output_path_error = Path(config.error_output["jsonl"]["output_file"]) + output_path2 = Path(config.output["second_output"]["output_file"]) + output_path_custom2 = Path(config.output["second_output"]["output_file_custom"]) config_path = tmp_path / "generated_config.yml" config_path.write_text(config.as_yaml()) proc = start_logprep(str(config_path)) wait_for_output(proc, "no documents left") stop_logprep(proc) - assert output_path1.read_text(), "output is not empty" - assert ( - output_path1.read_text() == output_path2.read_text() + assert output_path1.read_text("utf8"), "output is not empty" + assert output_path1.read_text("utf8") == output_path2.read_text( + "utf8" ), "stored output in both default outputs" - assert output_path_custom1.read_text(), "stored custom output in output with name 'jsonl'" - assert ( - not output_path_custom2.read_text() + assert output_path_custom1.read_text("utf8"), "stored custom output in output with name 'jsonl'" + assert not output_path_custom2.read_text( + "utf8" ), "stored custom output not in output with name 'second_output'" - assert not output_path_error1.read_text(), "no errors in processing for 'jsonl' output" - assert not output_path_error2.read_text(), "no errors in processing for 'second_output' output" + assert not output_path_error.read_text("utf8"), "no errors in processing" diff --git a/tests/acceptance/test_wineventlog_pseudonymization.py b/tests/acceptance/test_wineventlog_pseudonymization.py index e4f25dcda..b8f9909db 100644 --- a/tests/acceptance/test_wineventlog_pseudonymization.py +++ b/tests/acceptance/test_wineventlog_pseudonymization.py @@ -1,15 +1,19 @@ # pylint: disable=missing-docstring +import tempfile +import time from logging import DEBUG, basicConfig, getLogger -from os import path +from pathlib import Path +import msgspec import pytest from logprep.util.configuration import Configuration from logprep.util.json_handling import parse_jsonl from tests.acceptance.util import ( - get_default_logprep_config, get_difference, - get_test_output, + start_logprep, + stop_logprep, + wait_for_output, ) basicConfig(level=DEBUG, format="%(asctime)-15s %(name)-5s %(levelname)-8s: %(message)s") @@ -18,48 +22,87 @@ @pytest.fixture(name="config") def get_config(): - pipeline = [ - { - "pseudonymizer": { - "type": "pseudonymizer", - "pubkey_analyst": "tests/testdata/acceptance/pseudonymizer/example_analyst_pub.pem", - "pubkey_depseudo": "tests/testdata/acceptance/pseudonymizer/example_depseudo_pub.pem", - "hash_salt": "a_secret_tasty_ingredient", - "outputs": [{"jsonl": "pseudonyms"}], - "specific_rules": ["tests/testdata/acceptance/pseudonymizer/rules_static/specific"], - "generic_rules": ["tests/testdata/acceptance/pseudonymizer/rules_static/generic"], - "regex_mapping": "tests/testdata/acceptance/pseudonymizer/rules_static/regex_mapping.yml", - "max_cached_pseudonyms": 1000000, + config_dict = { + "process_count": 1, + "timeout": 0.1, + "profile_pipelines": False, + "logger": {"level": "DEBUG"}, + "pipeline": [ + { + "pseudonymizer": { + "type": "pseudonymizer", + "pubkey_analyst": "tests/testdata/acceptance/pseudonymizer/example_analyst_pub.pem", + "pubkey_depseudo": "tests/testdata/acceptance/pseudonymizer/example_depseudo_pub.pem", + "hash_salt": "a_secret_tasty_ingredient", + "outputs": [{"jsonl": "pseudonyms"}], + "specific_rules": [ + "tests/testdata/acceptance/pseudonymizer/rules_static/specific" + ], + "generic_rules": [ + "tests/testdata/acceptance/pseudonymizer/rules_static/generic" + ], + "regex_mapping": "tests/testdata/acceptance/pseudonymizer/rules_static/regex_mapping.yml", + "max_cached_pseudonyms": 1000000, + } } - } - ] - return get_default_logprep_config(pipeline, with_hmac=False) + ], + "input": { + "jsonl_input": { + "type": "jsonl_input", + "documents_path": "tests/testdata/input_logdata/wineventlog_raw.jsonl", + } + }, + "output": { + "jsonl": { + "type": "jsonl_output", + "output_file": tempfile.mktemp(suffix=".output.jsonl"), + "output_file_custom": tempfile.mktemp(suffix=".custom.jsonl"), + } + }, + "error_output": { + "jsonl": { + "type": "jsonl_output", + "output_file": tempfile.mktemp(suffix=".error.jsonl"), + } + }, + } + + return Configuration(**config_dict) + + +def teardown_function(): + Path("generated_config.yml").unlink(missing_ok=True) + stop_logprep() def test_events_pseudonymized_correctly(tmp_path, config: Configuration): - expected_output_file_name = "pseudonymized_win_event_log.jsonl" - expected_output_path = path.join( - "tests/testdata/acceptance/expected_result", expected_output_file_name + config_path = tmp_path / "generated_config.yml" + config_path.write_text(config.as_yaml()) + proc = start_logprep(config_path) + wait_for_output(proc, "Startup complete") + time.sleep(2) + expected_output_path = ( + "tests/testdata/acceptance/expected_result/pseudonymized_win_event_log.jsonl" ) expected_output = parse_jsonl(expected_output_path) expected_logprep_outputs = [ event for event in expected_output if "pseudonym" not in event.keys() ] - expected_logprep_extra_outputs = [ - event for event in expected_output if "pseudonym" in event.keys() - ] - - config.input["jsonl"]["documents_path"] = "tests/testdata/input_logdata/wineventlog_raw.jsonl" - config_path = tmp_path / "generated_config.yml" - config_path.write_text(config.as_yaml()) - - logprep_output, logprep_extra_output, logprep_error_output = get_test_output(str(config_path)) - assert logprep_output, "should not be empty" - assert len(logprep_error_output) == 0, "There shouldn't be any logprep errors" - result = get_difference(logprep_output, expected_logprep_outputs) + output = Path(config.output["jsonl"]["output_file"]).read_bytes() + extra_output = Path(config.output["jsonl"]["output_file_custom"]).read_bytes() + error_output = Path(config.error_output["jsonl"]["output_file"]).read_bytes() + decoder = msgspec.json.Decoder() + output = decoder.decode_lines(output) + extra_output = decoder.decode_lines(extra_output) + error_output = decoder.decode_lines(error_output) + assert output, "should not be empty" + assert len(error_output) == 0, "There shouldn't be any logprep errors" + assert extra_output, "extra outputs should not be empty" + assert extra_output[5].get("pseudonyms", {}).get("pseudonym"), "should have pseudonym key" + assert extra_output[5].get("pseudonyms", {}).get("origin"), "should have origin key" + assert extra_output[5].get("pseudonyms", {}).get("@timestamp"), "should have @timestamp key" + # Check the pseudonymized events + result = get_difference(output, expected_logprep_outputs) assert ( result["difference"][0] == result["difference"][1] ), f"Missmatch in event at line {result['event_line_no']}!" - - # FIXME: Test is only testing for the logprep outputs with the pseudonym inside, but not the - # extra outputs. diff --git a/tests/acceptance/util.py b/tests/acceptance/util.py index 9e8704ca7..04de101df 100644 --- a/tests/acceptance/util.py +++ b/tests/acceptance/util.py @@ -135,7 +135,10 @@ def get_runner_outputs(patched_runner: Runner) -> list: output_paths = [ output_path for key, output_path in output_config.items() if "output_file" in key ] - + if patched_runner._configuration.error_output: + config = list(patched_runner._configuration.error_output.values())[0] + if "output_file" in config: + output_paths.append(config["output_file"]) for output_path in output_paths: remove_file_if_exists(output_path) @@ -226,7 +229,6 @@ def get_default_logprep_config(pipeline_config, with_hmac=True) -> Configuration "type": "jsonl_output", "output_file": "tests/testdata/acceptance/test_kafka_data_processing_acceptance.out", "output_file_custom": "tests/testdata/acceptance/test_kafka_data_processing_acceptance_custom.out", - "output_file_error": "tests/testdata/acceptance/test_kafka_data_processing_acceptance_error.out", } }, } @@ -259,15 +261,26 @@ def start_logprep(config_path: str, env: dict = None) -> subprocess.Popen: ) -def wait_for_output(proc, expected_output, test_timeout=10): +def wait_for_output(proc, expected_output, test_timeout=10, forbidden_outputs=None): + if forbidden_outputs is None: + forbidden_outputs = ["Invalid", "Exception", "critical", "Error", "ERROR"] + @timeout(test_timeout) - def wait_for_output_inner(proc, expected_output): + def wait_for_output_inner( + proc, + expected_output, + forbidden_outputs, + ): output = proc.stdout.readline() - while not re.search(expected_output, output.decode("utf8")): + while 1: + if re.search(expected_output, output.decode("utf8")): + break + for forbidden_output in forbidden_outputs: + assert not re.search(forbidden_output, output.decode("utf8")), output output = proc.stdout.readline() - wait_for_output_inner(proc, expected_output) - time.sleep(0.1) # nosemgrep + wait_for_output_inner(proc, expected_output, forbidden_outputs) + time.sleep(0.1) def stop_logprep(proc=None): diff --git a/tests/testdata/config/config-docker.yml b/tests/testdata/config/config-docker.yml index 375c1dd0d..187771905 100644 --- a/tests/testdata/config/config-docker.yml +++ b/tests/testdata/config/config-docker.yml @@ -21,7 +21,6 @@ output: kafka: type: confluentkafka_output topic: wineventlog_labeled - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: diff --git a/tests/testdata/config/config.yml b/tests/testdata/config/config.yml index 846c20aaf..f9e05bbee 100644 --- a/tests/testdata/config/config.yml +++ b/tests/testdata/config/config.yml @@ -52,7 +52,6 @@ output: kafka_output: type: confluentkafka_output topic: producer - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: @@ -62,7 +61,6 @@ output: kafka: type: confluentkafka_output topic: producer - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: diff --git a/tests/testdata/config/config2.yml b/tests/testdata/config/config2.yml index d11a57b47..30a89d051 100644 --- a/tests/testdata/config/config2.yml +++ b/tests/testdata/config/config2.yml @@ -23,7 +23,6 @@ output: kafka: type: confluentkafka_output topic: producer3 - error_topic: producer_error3 flush_timeout: 30 send_timeout: 2 kafka_config: diff --git a/tests/unit/charts/test_error_output_config.py b/tests/unit/charts/test_error_output_config.py new file mode 100644 index 000000000..6218ea2b3 --- /dev/null +++ b/tests/unit/charts/test_error_output_config.py @@ -0,0 +1,86 @@ +# pylint: disable=missing-docstring +# pylint: disable=attribute-defined-outside-init +# pylint: disable=protected-access + + +from logprep.util.configuration import yaml +from tests.unit.charts.test_base import TestBaseChartTest + +kafka_output_config = { + "flush_timeout": 300, + "kafka_config": { + "batch.size": 100, + "bootstrap.servers": "127.0.0.1:9092", + "compression.type": "none", + "queue.buffering.max.kbytes": 1024, + "queue.buffering.max.messages": 10, + "queue.buffering.max.ms": 1000, + "request.required.acks": -1, + "statistics.interval.ms": 60000, + }, + "send_timeout": 0, + "topic": "errors", + "type": "confluentkafka_output", +} + + +class TestErrorOutputConfig(TestBaseChartTest): + + def test_error_output_config_file_is_set(self): + expected_output_config = { + "error_output": { + "confluentkafka": kafka_output_config, + } + } + self.manifests = self.render_chart("logprep", {"error_output": kafka_output_config}) + expected_output_config = yaml.dump(expected_output_config) + error_output_config = self.manifests.by_query( + "kind: ConfigMap AND metadata.name: logprep-logprep-error-output" + ) + assert error_output_config + error_output_config = error_output_config[0] + assert error_output_config["data"]["error-output-config.yaml"] == expected_output_config + + def test_deployment_mounts_error_output_config(self): + self.manifests = self.render_chart("logprep", {"error_output": kafka_output_config}) + deployment = self.manifests.by_query("kind: Deployment")[0] + volume_mounts = deployment["spec.template.spec.containers"][0]["volumeMounts"] + volume_mount = [mount for mount in volume_mounts if mount["name"] == "error-output-config"][ + 0 + ] + assert volume_mount + assert volume_mount["mountPath"] == "/home/logprep/error-output-config.yaml" + assert volume_mount["subPath"] == "error-output-config.yaml" + + def test_error_output_config_volume_is_populated(self): + self.manifests = self.render_chart("logprep", {"error_output": kafka_output_config}) + deployment = self.manifests.by_query("kind: Deployment")[0] + error_output_config = self.manifests.by_query( + "kind: ConfigMap AND metadata.name: logprep-logprep-error-output" + ) + error_output_config_name = error_output_config[0]["metadata"]["name"] + volumes = deployment["spec.template.spec.volumes"] + volume = [vol for vol in volumes if vol["name"] == "error-output-config"][0] + assert volume + assert volume["configMap"]["name"] == error_output_config_name + + def test_error_output_config_is_used_in_start_command_of_logprep(self): + self.manifests = self.render_chart("logprep", {"error_output": kafka_output_config}) + container = self.deployment["spec.template.spec.containers"][0] + volume_mounts = container["volumeMounts"] + volume_mount = [mount for mount in volume_mounts if mount["name"] == "error-output-config"][ + 0 + ] + assert volume_mount["subPath"] in " ".join(container["command"]) + + def test_error_output_is_not_rendered_if_no_error_output(self): + self.manifests = self.render_chart("logprep", {"error_output": {}}) + error_output_config = self.manifests.by_query( + "kind: ConfigMap AND metadata.name: logprep-logprep-error-output" + ) + assert not error_output_config + container = self.deployment["spec.template.spec.containers"][0] + volume_mounts = container["volumeMounts"] + volume_mount = [mount["name"] for mount in volume_mounts] + assert "error-output-config" not in volume_mount + assert "error-output-config.yaml" not in " ".join(container["command"]) diff --git a/tests/unit/charts/test_output_config.py b/tests/unit/charts/test_output_config.py index 030d7d1ce..913fb9410 100644 --- a/tests/unit/charts/test_output_config.py +++ b/tests/unit/charts/test_output_config.py @@ -9,7 +9,6 @@ opensearch_config = { "ca_cert": "/path/to/cert.crt", "default_index": "default_index", - "error_index": "error_index", "hosts": ["127.0.0.1:9200"], "message_backlog_size": 10000, "timeout": 10000, diff --git a/tests/unit/connector/base.py b/tests/unit/connector/base.py index 010c1e214..ec8906cb9 100644 --- a/tests/unit/connector/base.py +++ b/tests/unit/connector/base.py @@ -10,8 +10,10 @@ from logging import getLogger from unittest import mock +import pytest + from logprep.abc.connector import Connector -from logprep.abc.input import Input +from logprep.abc.input import CriticalInputError, Input from logprep.abc.output import Output from logprep.factory import Factory from logprep.util.time import TimeParser @@ -26,7 +28,6 @@ class BaseConnectorTestCase(BaseComponentTestCase): expected_metrics = [ "logprep_processing_time_per_event", "logprep_number_of_processed_events", - "logprep_number_of_failed_events", "logprep_number_of_warnings", "logprep_number_of_errors", ] @@ -42,7 +43,7 @@ def test_is_input_instance(self): def test_get_next_returns_event(self): return_value = ({"message": "test message"}, b'{"message": "test message"}') self.object._get_event = mock.MagicMock(return_value=return_value) - event, _ = self.object.get_next(0.01) + event = self.object.get_next(0.01) assert isinstance(event, dict) def test_add_hmac_returns_true_if_hmac_options(self): @@ -75,10 +76,7 @@ def test_add_hmac_to_adds_hmac(self): } ) connector = Factory.create({"test connector": connector_config}) - processed_event, non_critical_error_msg = connector._add_hmac_to( - {"message": "test message"}, b"test message" - ) - assert non_critical_error_msg is None + processed_event = connector._add_hmac_to({"message": "test message"}, b"test message") assert processed_event.get("Hmac") assert ( processed_event.get("Hmac").get("hmac") @@ -102,10 +100,7 @@ def test_add_hmac_to_adds_hmac_even_if_no_raw_message_was_given(self): } ) connector = Factory.create({"test connector": connector_config}) - processed_event, non_critical_error_msg = connector._add_hmac_to( - {"message": "test message"}, None - ) - assert non_critical_error_msg is None + processed_event = connector._add_hmac_to({"message": "test message"}, None) assert processed_event.get("Hmac") calculated_hmac = processed_event.get("Hmac").get("hmac") assert ( @@ -142,7 +137,7 @@ def test_get_next_with_hmac_of_raw_message(self): "hmac": "dfe78753da634d7b76760488dbb2cf7bfe1b0e4e794930c36e98a984b6b6be63", }, } - connector_next_msg, _ = connector.get_next(1) + connector_next_msg = connector.get_next(1) assert connector_next_msg == expected_event, "Output event with hmac is not as expected" decoded = base64.b64decode(connector_next_msg["Hmac"]["compressed_base64"]) @@ -178,7 +173,7 @@ def test_get_next_with_hmac_of_subfield(self): }, } - connector_next_msg, _ = connector.get_next(1) + connector_next_msg = connector.get_next(1) assert connector_next_msg == expected_event decoded = base64.b64decode(connector_next_msg["Hmac"]["compressed_base64"]) @@ -206,20 +201,10 @@ def test_get_next_with_hmac_of_non_existing_subfield(self): connector._get_event = mock.MagicMock( return_value=(test_event.copy(), raw_encoded_test_event) ) - expected_output_event = { - "message": {"with_subfield": "content"}, - "Hmac": { - "hmac": "error", - "compressed_base64": "eJyzSa0oSE0uSU1RyMhNTFYoSSxKTy1RSMtMzUlRUM/Lz4tPrcgsLsnMS48Hi" - "6kr5OUDpfNL81LsAJILFeQ=", - }, - } - connector_next_msg, non_critical_error_msg = connector.get_next(1) - assert connector_next_msg == expected_output_event - decoded = base64.b64decode(connector_next_msg["Hmac"]["compressed_base64"]) - decoded_message = zlib.decompress(decoded).decode("utf8") - assert decoded_message == "" - assert non_critical_error_msg == "Couldn't find the hmac target field 'non_existing_field'" + critical_input_error_msg = "Couldn't find the hmac target field 'non_existing_field'" + with pytest.raises(CriticalInputError, match=critical_input_error_msg) as error: + _ = connector.get_next(1) + assert error.value.raw_input == b'{"message":{"with_subfield":"content"}}' def test_get_next_with_hmac_result_in_dotted_subfield(self): connector_config = deepcopy(self.CONFIG) @@ -252,7 +237,7 @@ def test_get_next_with_hmac_result_in_dotted_subfield(self): }, } - connector_next_msg, _ = connector.get_next(1) + connector_next_msg = connector.get_next(1) assert connector_next_msg == expected_event decoded = base64.b64decode( connector_next_msg["Hmac"]["dotted"]["subfield"]["compressed_base64"] @@ -281,11 +266,10 @@ def test_get_next_with_hmac_result_in_already_existing_subfield(self): connector._get_event = mock.MagicMock( return_value=(test_event.copy(), raw_encoded_test_event) ) - _, non_critical_error_msg = connector.get_next(1) - assert ( - non_critical_error_msg - == "Couldn't add the hmac to the input event as the desired output field 'message' already exist." - ) + non_critical_error_msg = "Couldn't add the hmac to the input event as the desired output field 'message' already exist." + with pytest.raises(CriticalInputError, match=non_critical_error_msg) as error: + _ = connector.get_next(1) + assert error.value.raw_input == {"message": {"with_subfield": "content"}} def test_get_next_without_hmac(self): connector_config = deepcopy(self.CONFIG) @@ -296,7 +280,7 @@ def test_get_next_without_hmac(self): connector._get_event = mock.MagicMock( return_value=(test_event.copy(), raw_encoded_test_event) ) - connector_next_msg, _ = connector.get_next(1) + connector_next_msg = connector.get_next(1) assert connector_next_msg == test_event def test_preprocessing_version_info_is_added_if_configured(self): @@ -312,7 +296,7 @@ def test_preprocessing_version_info_is_added_if_configured(self): connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result.get("version_info", {}).get("logprep") == "3.3.0" assert result.get("version_info", {}).get("configuration") == "unset" @@ -328,7 +312,7 @@ def test_pipeline_preprocessing_does_not_add_versions_if_target_field_exists_alr connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content", "version_info": "something random"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == {"any": "content", "version_info": "something random"} def test_pipeline_preprocessing_only_version_information(self): @@ -342,7 +326,7 @@ def test_pipeline_preprocessing_only_version_information(self): connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content", "version_info": "something random"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == {"any": "content", "version_info": "something random"} def test_get_raw_event_is_callable(self): @@ -372,7 +356,7 @@ def test_get_next_adds_timestamp_if_configured(self): connector_config.update(preprocessing_config) connector = Factory.create({"test connector": connector_config}) connector._get_event = mock.MagicMock(return_value=({"any": "content"}, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) target_field = preprocessing_config.get("preprocessing", {}).get( "log_arrival_time_target_field" ) @@ -393,7 +377,7 @@ def test_pipeline_preprocessing_does_not_add_log_arrival_time_if_target_field_ex connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content", "arrival_time": "does not matter"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == {"any": "content", "arrival_time": "does not matter"} def test_pipeline_preprocessing_adds_timestamp_delta_if_configured(self): @@ -411,7 +395,7 @@ def test_pipeline_preprocessing_adds_timestamp_delta_if_configured(self): connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content", "@timestamp": "1999-09-09T09:09:09.448319+02:00"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) target_field = ( preprocessing_config.get("preprocessing") .get("log_arrival_timedelta") @@ -437,7 +421,7 @@ def test_pipeline_preprocessing_does_not_add_timestamp_delta_if_configured_but_r connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert "arrival_time" in result assert "log_arrival_timedelta" not in result @@ -452,7 +436,7 @@ def test_pipeline_preprocessing_does_not_add_timestamp_delta_if_not_configured(s connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert "arrival_time" in result def test_pipeline_preprocessing_does_not_add_timestamp_delta_if_configured_but_log_arrival_timestamp_not( @@ -471,7 +455,7 @@ def test_pipeline_preprocessing_does_not_add_timestamp_delta_if_configured_but_l connector = Factory.create({"test connector": connector_config}) test_event = {"any": "content"} connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == {"any": "content"} def test_preprocessing_enriches_by_env_variable(self): @@ -488,7 +472,7 @@ def test_preprocessing_enriches_by_env_variable(self): test_event = {"any": "content"} os.environ["TEST_ENV_VARIABLE"] = "test_value" connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == {"any": "content", "enriched_field": "test_value"} def test_preprocessing_enriches_by_multiple_env_variables(self): @@ -507,7 +491,7 @@ def test_preprocessing_enriches_by_multiple_env_variables(self): os.environ["TEST_ENV_VARIABLE_FOO"] = "test_value_foo" os.environ["TEST_ENV_VARIABLE_BAR"] = "test_value_bar" connector._get_event = mock.MagicMock(return_value=(test_event, None)) - result, _ = connector.get_next(0.01) + result = connector.get_next(0.01) assert result == { "any": "content", "enriched_field1": "test_value_foo", @@ -521,7 +505,7 @@ def test_get_next_counts_number_of_processed_events(self): self.object.get_next(0.01) assert self.object.metrics.number_of_processed_events == 1 - def test_get_next_doesnt_count_numer_of_processed_events_if_event_is_none(self): + def test_get_next_does_not_count_number_of_processed_events_if_event_is_none(self): self.object.metrics.number_of_processed_events = 0 self.object._get_event = mock.MagicMock(return_value=(None, None)) self.object.get_next(0.01) @@ -546,13 +530,3 @@ def test_store_counts_processed_events(self): self.object.metrics.number_of_processed_events = 0 self.object.store({"message": "my event message"}) assert self.object.metrics.number_of_processed_events == 1 - - def test_store_failed_counts_failed_events(self): - self.object.metrics.number_of_failed_events = 0 - self.object.store_failed("error", {"message": "my event message"}, {}) - assert self.object.metrics.number_of_failed_events == 1 - - def test_store_calls_batch_finished_callback(self): - self.object.input_connector = mock.MagicMock() - self.object.store({"message": "my event message"}) - self.object.input_connector.batch_finished_callback.assert_called() diff --git a/tests/unit/connector/test_confluent_kafka_input.py b/tests/unit/connector/test_confluent_kafka_input.py index adac8003e..e2c2ebd2d 100644 --- a/tests/unit/connector/test_confluent_kafka_input.py +++ b/tests/unit/connector/test_confluent_kafka_input.py @@ -3,12 +3,13 @@ # pylint: disable=wrong-import-position # pylint: disable=wrong-import-order # pylint: disable=attribute-defined-outside-init +import os import socket from copy import deepcopy from unittest import mock import pytest -from confluent_kafka import OFFSET_BEGINNING, KafkaError, KafkaException +from confluent_kafka import OFFSET_BEGINNING, KafkaError, KafkaException, Message from logprep.abc.input import ( CriticalInputError, @@ -54,7 +55,6 @@ class TestConfluentKafkaInput(BaseInputTestCase, CommonConfluentKafkaTestCase): "logprep_confluent_kafka_input_librdkafka_tx_bytes", "logprep_processing_time_per_event", "logprep_number_of_processed_events", - "logprep_number_of_failed_events", "logprep_number_of_warnings", "logprep_number_of_errors", ] @@ -62,9 +62,8 @@ class TestConfluentKafkaInput(BaseInputTestCase, CommonConfluentKafkaTestCase): @mock.patch("logprep.connector.confluent_kafka.input.Consumer") def test_get_next_returns_none_if_no_records(self, _): self.object._consumer.poll = mock.MagicMock(return_value=None) - event, non_critical_error_msg = self.object.get_next(1) + event = self.object.get_next(1) assert event is None - assert non_critical_error_msg is None @mock.patch("logprep.connector.confluent_kafka.input.Consumer") def test_get_next_raises_critical_input_exception_for_invalid_confluent_kafka_record(self, _): @@ -87,10 +86,10 @@ def test_get_next_raises_critical_input_exception_for_invalid_confluent_kafka_re r"CriticalInputError in ConfluentKafkaInput \(Test Instance Name\) - " r"Kafka Input: testserver:9092: " r"A confluent-kafka record contains an error code -> " - r"KafkaError{code=UNKNOWN_TOPIC_OR_PART,val=3,str=\"Subscribed topic not available: \(Test Instance Name\) : Broker: Unknown topic or partition\"}" + r"event was written to error output if configured" ), ): - _, _ = self.object.get_next(1) + _ = self.object.get_next(1) @mock.patch("logprep.connector.confluent_kafka.input.Consumer") def test_shut_down_calls_consumer_close(self, _): @@ -104,7 +103,7 @@ def test_batch_finished_callback_calls_store_offsets(self, _): kafka_input = Factory.create({"test": input_config}) kafka_consumer = kafka_input._consumer message = "test message" - kafka_input._last_valid_records = {0: message} + kafka_input._last_valid_record = message kafka_input.batch_finished_callback() kafka_consumer.store_offsets.assert_called() kafka_consumer.store_offsets.assert_called_with(message=message) @@ -180,9 +179,13 @@ def test_get_event_raises_exception_if_input_invalid_json(self, _): mock_record.value.return_value = '{"invalid_json"}'.encode("utf8") with pytest.raises( CriticalInputParsingError, - match="Input record value is not a valid json string -> b'{\"invalid_json\"}'", - ): + match=( + r"Input record value is not a valid json string ->" + r" event was written to error output if configured" + ), + ) as error: self.object._get_event(0.001) + assert error.value.raw_input == b'{"invalid_json"}' @mock.patch("logprep.connector.confluent_kafka.input.Consumer") def test_get_event_raises_exception_if_input_not_utf(self, _): @@ -194,9 +197,13 @@ def test_get_event_raises_exception_if_input_not_utf(self, _): mock_record.value.return_value = '{"not_utf-8": \xfc}'.encode("cp1252") with pytest.raises( CriticalInputParsingError, - match=r"Input record value is not \'utf-8\' encoded -> b\'\{\"not_utf-8\": \\xfc\}\'", - ): + match=( + r"Input record value is not \'utf-8\' encoded ->" + r" event was written to error output if configured" + ), + ) as error: self.object._get_event(0.001) + assert error.value.raw_input == "b'{\"not_utf-8\": \\xfc}'" def test_setup_raises_fatal_input_error_on_invalid_config(self): kafka_config = { @@ -247,6 +254,7 @@ def test_default_config_is_injected(self, mock_consumer): "statistics.interval.ms": "30000", "bootstrap.servers": "testserver:9092", "group.id": "testgroup", + "group.instance.id": f"{socket.getfqdn().strip('.')}-PipelineNone-pid{os.getpid()}", "logger": logger, "on_commit": self.object._commit_callback, "stats_cb": self.object._stats_callback, @@ -270,26 +278,28 @@ def test_auto_offset_store_and_auto_commit_are_managed_by_connector(self, mock_c assert injected_config.get("enable.auto.commit") == "true" @mock.patch("logprep.connector.confluent_kafka.input.Consumer") - def test_client_id_can_be_overwritten(self, mock_consumer): + @mock.patch("logprep.connector.confluent_kafka.input.AdminClient") + def test_client_id_can_be_overwritten(self, _, mock_consumer): input_config = deepcopy(self.CONFIG) input_config["kafka_config"]["client.id"] = "thisclientid" kafka_input = Factory.create({"test": input_config}) metadata = mock.MagicMock() metadata.topics = [kafka_input._config.topic] - kafka_input._consumer.list_topics.return_value = metadata + kafka_input._admin.list_topics.return_value = metadata kafka_input.setup() mock_consumer.assert_called() assert mock_consumer.call_args[0][0].get("client.id") == "thisclientid" assert not mock_consumer.call_args[0][0].get("client.id") == socket.getfqdn() @mock.patch("logprep.connector.confluent_kafka.input.Consumer") - def test_statistics_interval_can_be_overwritten(self, mock_consumer): + @mock.patch("logprep.connector.confluent_kafka.input.AdminClient") + def test_statistics_interval_can_be_overwritten(self, _, mock_consumer): input_config = deepcopy(self.CONFIG) input_config["kafka_config"]["statistics.interval.ms"] = "999999999" kafka_input = Factory.create({"test": input_config}) metadata = mock.MagicMock() metadata.topics = [kafka_input._config.topic] - kafka_input._consumer.list_topics.return_value = metadata + kafka_input._admin.list_topics.return_value = metadata kafka_input.setup() mock_consumer.assert_called() assert mock_consumer.call_args[0][0].get("statistics.interval.ms") == "999999999" @@ -366,21 +376,18 @@ def test_revoke_callback_logs_warning_and_counts(self, mock_consumer): assert self.object.metrics.number_of_warnings == 1 @mock.patch("logprep.connector.confluent_kafka.input.Consumer") - def test_revoke_callback_writes_output_backlog_and_calls_batch_finished_callback( - self, mock_consumer - ): + def test_revoke_callback_calls_batch_finished_callback(self, mock_consumer): self.object.output_connector = mock.MagicMock() self.object.batch_finished_callback = mock.MagicMock() mock_partitions = [mock.MagicMock()] self.object._revoke_callback(mock_consumer, mock_partitions) - self.object.output_connector._write_backlog.assert_called() self.object.batch_finished_callback.assert_called() def test_health_returns_true_if_no_error(self): - self.object._consumer = mock.MagicMock() + self.object._admin = mock.MagicMock() metadata = mock.MagicMock() metadata.topics = [self.object._config.topic] - self.object._consumer.list_topics.return_value = metadata + self.object._admin.list_topics.return_value = metadata assert self.object.health() def test_health_returns_false_if_topic_not_present(self): diff --git a/tests/unit/connector/test_confluent_kafka_output.py b/tests/unit/connector/test_confluent_kafka_output.py index 6cdd4c964..cb79c52c4 100644 --- a/tests/unit/connector/test_confluent_kafka_output.py +++ b/tests/unit/connector/test_confluent_kafka_output.py @@ -27,7 +27,6 @@ class TestConfluentKafkaOutput(BaseOutputTestCase, CommonConfluentKafkaTestCase) CONFIG = { "type": "confluentkafka_output", "topic": "test_input_raw", - "error_topic": "test_error_topic", "flush_timeout": 0.1, "kafka_config": { "bootstrap.servers": "testserver:9092", @@ -48,7 +47,6 @@ class TestConfluentKafkaOutput(BaseOutputTestCase, CommonConfluentKafkaTestCase) "logprep_confluent_kafka_output_librdkafka_txmsg_bytes", "logprep_processing_time_per_event", "logprep_number_of_processed_events", - "logprep_number_of_failed_events", "logprep_number_of_warnings", "logprep_number_of_errors", ] @@ -78,24 +76,6 @@ def test_store_custom_sends_event_to_expected_topic(self, _): kafka_producer.produce.assert_called() assert expected_call in kafka_producer.produce.mock_calls - @mock.patch("logprep.connector.confluent_kafka.output.Producer") - def test_store_failed_calls_producer_produce(self, _): - kafka_producer = self.object._producer - event_received = {"field": "received"} - event = {"field": "content"} - error_message = "error message" - self.object.store_failed(error_message, event_received, event) - kafka_producer.produce.assert_called() - mock_produce_call = kafka_producer.produce.mock_calls[0] - assert self.CONFIG.get("error_topic") in mock_produce_call[1] - assert "value" in mock_produce_call[2] - mock_produce_call_value = mock_produce_call[2].get("value") - mock_produce_call_value = json.loads(mock_produce_call_value.decode("utf8")) - assert "error" in mock_produce_call_value - assert "original" in mock_produce_call_value - assert "processed" in mock_produce_call_value - assert "timestamp" in mock_produce_call_value - @mock.patch("logprep.connector.confluent_kafka.output.Producer") def test_store_custom_calls_producer_flush_on_buffererror(self, _): kafka_producer = self.object._producer @@ -103,15 +83,6 @@ def test_store_custom_calls_producer_flush_on_buffererror(self, _): self.object.store_custom({"message": "does not matter"}, "doesnotcare") kafka_producer.flush.assert_called() - @mock.patch("logprep.connector.confluent_kafka.output.Producer") - def test_store_failed_calls_producer_flush_on_buffererror(self, _): - kafka_producer = self.object._producer - kafka_producer.produce.side_effect = BufferError - self.object.store_failed( - "doesnotcare", {"message": "does not matter"}, {"message": "does not matter"} - ) - kafka_producer.flush.assert_called() - @mock.patch("logprep.connector.confluent_kafka.output.Producer") def test_shut_down_calls_producer_flush(self, _): kafka_producer = self.object._producer @@ -121,20 +92,15 @@ def test_shut_down_calls_producer_flush(self, _): @mock.patch("logprep.connector.confluent_kafka.output.Producer") def test_raises_critical_output_on_any_exception(self, _): self.object._producer.produce.side_effect = [ - BaseException("bad things happened"), + Exception("bad things happened"), None, None, ] - self.object.store_failed = mock.MagicMock() with pytest.raises( CriticalOutputError, - match=r"CriticalOutputError in ConfluentKafkaOutput" - r" \(Test Instance Name\) - Kafka Output: testserver:9092: " - r"Error storing output document -> bad things happened for event: " - r"\{'message': 'test message'\}", + match=r"bad things happened", ): self.object.store({"message": "test message"}) - self.object.store_failed.assert_called() @mock.patch("logprep.connector.confluent_kafka.output.Producer") def test_store_counts_processed_events(self, _): # pylint: disable=arguments-differ @@ -142,12 +108,6 @@ def test_store_counts_processed_events(self, _): # pylint: disable=arguments-di self.object.store({"message": "my event message"}) assert self.object.metrics.number_of_processed_events == 1 - @mock.patch("logprep.connector.confluent_kafka.output.Producer") - def test_store_calls_batch_finished_callback(self, _): # pylint: disable=arguments-differ - self.object.input_connector = mock.MagicMock() - self.object.store({"message": "my event message"}) - self.object.input_connector.batch_finished_callback.assert_called() - def test_setup_raises_fatal_output_error_on_invalid_config(self): kafka_config = {"myconfig": "the config", "bootstrap.servers": "testserver:9092"} config = deepcopy(self.CONFIG) @@ -164,35 +124,35 @@ def test_raises_value_error_if_mandatory_parameters_not_set(self): Factory.create({"test": config}) def test_health_returns_true_if_no_error(self): - self.object._producer = mock.MagicMock() + self.object._admin = mock.MagicMock() metadata = mock.MagicMock() metadata.topics = [self.object._config.topic] - self.object._producer.list_topics.return_value = metadata + self.object._admin.list_topics.return_value = metadata assert self.object.health() def test_health_returns_false_if_topic_not_present(self): - self.object._producer = mock.MagicMock() + self.object._admin = mock.MagicMock() metadata = mock.MagicMock() metadata.topics = ["not_the_topic"] - self.object._producer.list_topics.return_value = metadata + self.object._admin.list_topics.return_value = metadata assert not self.object.health() def test_health_returns_false_on_kafka_exception(self): - self.object._producer = mock.MagicMock() - self.object._producer.list_topics.side_effect = KafkaException("test error") + self.object._admin = mock.MagicMock() + self.object._admin.list_topics.side_effect = KafkaException("test error") assert not self.object.health() def test_health_logs_error_on_kafka_exception(self): - self.object._producer = mock.MagicMock() - self.object._producer.list_topics.side_effect = KafkaException("test error") + self.object._admin = mock.MagicMock() + self.object._admin.list_topics.side_effect = KafkaException("test error") with mock.patch("logging.Logger.error") as mock_error: self.object.health() mock_error.assert_called() def test_health_counts_metrics_on_kafka_exception(self): self.object.metrics.number_of_errors = 0 - self.object._producer = mock.MagicMock() - self.object._producer.list_topics.side_effect = KafkaException("test error") + self.object._admin = mock.MagicMock() + self.object._admin.list_topics.side_effect = KafkaException("test error") assert not self.object.health() assert self.object.metrics.number_of_errors == 1 diff --git a/tests/unit/connector/test_console_output.py b/tests/unit/connector/test_console_output.py index d6f10c44b..cc856c9e8 100644 --- a/tests/unit/connector/test_console_output.py +++ b/tests/unit/connector/test_console_output.py @@ -35,9 +35,3 @@ def test_store_custom_calls_pprint_with_message_and_stream(self, mock_pprint): message = {"message": "mymessage"} self.object.store_custom(message, target="stdout") mock_pprint.assert_called_with(message, stream=sys.stdout) - - @mock.patch("logprep.connector.console.output.pprint") - def test_store_failed_calls_pprint_with_message_on_stderr(self, mock_pprint): - message = {"message": "mymessage"} - self.object.store_failed("myerrormessage", message, message) - mock_pprint.assert_called_with(f"myerrormessage: {message}, {message}", stream=sys.stderr) diff --git a/tests/unit/connector/test_dummy_input.py b/tests/unit/connector/test_dummy_input.py index 85973e656..8580bd68f 100644 --- a/tests/unit/connector/test_dummy_input.py +++ b/tests/unit/connector/test_dummy_input.py @@ -28,18 +28,18 @@ def test_returns_documents_in_order_provided(self): config["documents"] = [{"order": 0}, {"order": 1}, {"order": 2}] self.object = Factory.create({"Test Instance Name": config}) for order in range(0, 3): - event, _ = self.object.get_next(self.timeout) + event = self.object.get_next(self.timeout) assert event.get("order") == order def test_raises_exceptions_instead_of_returning_them_in_document(self): config = copy.deepcopy(self.CONFIG) config["documents"] = [{"order": 0}, DummyError, {"order": 1}] self.object = Factory.create({"Test Instance Name": config}) - event, _ = self.object.get_next(self.timeout) + event = self.object.get_next(self.timeout) assert event.get("order") == 0 with raises(DummyError): _, _ = self.object.get_next(self.timeout) - event, _ = self.object.get_next(self.timeout) + event = self.object.get_next(self.timeout) assert event.get("order") == 1 def test_raises_exceptions_instead_of_returning_them(self): @@ -56,5 +56,5 @@ def test_repeat_documents_repeats_documents(self): connector = Factory.create(configuration={"Test Instance Name": config}) for order in range(0, 9): - event, _ = connector.get_next(self.timeout) + event = connector.get_next(self.timeout) assert event.get("order") == order % 3 diff --git a/tests/unit/connector/test_dummy_output.py b/tests/unit/connector/test_dummy_output.py index b2607953b..7136111d0 100644 --- a/tests/unit/connector/test_dummy_output.py +++ b/tests/unit/connector/test_dummy_output.py @@ -77,13 +77,3 @@ def test_raises_exception_only_when_not_none(self): with raises(Exception, match="FatalOutputError"): dummy_output.store({"order": 1}) dummy_output.store({"order": 2}) - - def test_stores_failed_events_in_respective_list(self): - self.object.store_failed("message", {"doc": "received"}, {"doc": "processed"}) - - assert len(self.object.failed_events) == 1 - assert self.object.failed_events[0] == ( - "message", - {"doc": "received"}, - {"doc": "processed"}, - ) diff --git a/tests/unit/connector/test_file_input_default_config.py b/tests/unit/connector/test_file_input_default_config.py index 2f78dcdff..4f55df341 100644 --- a/tests/unit/connector/test_file_input_default_config.py +++ b/tests/unit/connector/test_file_input_default_config.py @@ -149,7 +149,7 @@ def test_input_line_function_returns_empty_string(self): def test_log_from_file_with_get_next(self): wait_for_interval(CHECK_INTERVAL) get_next_log_line = self.object.get_next(timeout=0.001) - assert get_next_log_line[0].get("message") == test_initial_log_data[0] + assert get_next_log_line.get("message") == test_initial_log_data[0] def test_log_from_file_is_put_in_queue(self): wait_for_interval(CHECK_INTERVAL) diff --git a/tests/unit/connector/test_http_input.py b/tests/unit/connector/test_http_input.py index c094cbf26..2b945530d 100644 --- a/tests/unit/connector/test_http_input.py +++ b/tests/unit/connector/test_http_input.py @@ -213,7 +213,7 @@ def test_jsonl_messages_are_put_in_queue(self): def test_get_next_returns_message_from_queue(self): data = {"message": "my log message"} requests.post(url=f"{self.target}/json", json=data, timeout=0.5) - assert self.object.get_next(0.001) == (data, None) + assert self.object.get_next(0.001) == data def test_get_next_returns_first_in_first_out(self): data = [ @@ -223,9 +223,9 @@ def test_get_next_returns_first_in_first_out(self): ] for message in data: requests.post(url=self.target + "/json", json=message, timeout=0.5) - assert self.object.get_next(0.001) == (data[0], None) - assert self.object.get_next(0.001) == (data[1], None) - assert self.object.get_next(0.001) == (data[2], None) + assert self.object.get_next(0.001) == data[0] + assert self.object.get_next(0.001) == data[1] + assert self.object.get_next(0.001) == data[2] def test_get_next_returns_first_in_first_out_for_mixed_endpoints(self): data = [ @@ -239,12 +239,12 @@ def test_get_next_returns_first_in_first_out_for_mixed_endpoints(self): requests.post(url=self.target + "/json", json=post_data, timeout=0.5) if endpoint == "plaintext": requests.post(url=self.target + "/plaintext", data=post_data, timeout=0.5) - assert self.object.get_next(0.001)[0] == data[0].get("data") - assert self.object.get_next(0.001)[0] == {"message": data[1].get("data")} - assert self.object.get_next(0.001)[0] == data[2].get("data") + assert self.object.get_next(0.001) == data[0].get("data") + assert self.object.get_next(0.001) == {"message": data[1].get("data")} + assert self.object.get_next(0.001) == data[2].get("data") def test_get_next_returns_none_for_empty_queue(self): - assert self.object.get_next(0.001)[0] is None + assert self.object.get_next(0.001) is None def test_server_returns_uvicorn_server_instance(self): assert isinstance(self.object.http_server.server, uvicorn.Server) @@ -321,7 +321,7 @@ def test_get_next_with_hmac_of_raw_message(self): "hmac": "f0221a62c4ea38a4cc3af176faba010212e0ce7e0052c71fe726cbf3cb03dfd1", }, } - connector_next_msg, _ = connector.get_next(1) + connector_next_msg = connector.get_next(1) assert connector_next_msg == expected_event, "Output event with hmac is not as expected" def test_endpoint_returns_401_if_authorization_not_provided(self, credentials_file_path): diff --git a/tests/unit/connector/test_http_output.py b/tests/unit/connector/test_http_output.py index 686aec190..553181452 100644 --- a/tests/unit/connector/test_http_output.py +++ b/tests/unit/connector/test_http_output.py @@ -26,6 +26,7 @@ class TestOutput(BaseOutputTestCase): "logprep_status_codes", "logprep_timeouts", "logprep_connection_errors", + "logprep_number_of_failed_events", ] @responses.activate @@ -50,13 +51,6 @@ def test_404_status_code(self): assert self.object.metrics.number_of_processed_events == 0 assert self.object.metrics.number_of_http_requests == 1 - @responses.activate - def test_store_calls_batch_finished_callback(self): - responses.add(responses.POST, f"{TARGET_URL}/", status=200) - self.object.input_connector = mock.MagicMock() - self.object.store({"message": "my event message"}) - self.object.input_connector.batch_finished_callback.assert_called() - @pytest.mark.parametrize( "testcase, input_data, number_of_expected_requests, number_of_expeted_events", [ diff --git a/tests/unit/connector/test_json_input.py b/tests/unit/connector/test_json_input.py index 5b850045c..93095fad5 100644 --- a/tests/unit/connector/test_json_input.py +++ b/tests/unit/connector/test_json_input.py @@ -32,15 +32,15 @@ def test_documents_returns(self, mock_parse): def test_get_next_returns_document(self, mock_parse): mock_parse.return_value = [{"message": "test_message"}] expected = {"message": "test_message"} - document, _ = self.object.get_next(self.timeout) + document = self.object.get_next(self.timeout) assert document == expected @mock.patch(parse_function) def test_get_next_returns_multiple_documents(self, mock_parse): mock_parse.return_value = [{"order": 0}, {"order": 1}] - event, _ = self.object.get_next(self.timeout) + event = self.object.get_next(self.timeout) assert {"order": 0} == event - event, _ = self.object.get_next(self.timeout) + event = self.object.get_next(self.timeout) assert {"order": 1} == event @mock.patch(parse_function) @@ -53,19 +53,19 @@ def test_raises_exception_if_not_a_dict(self, mock_parse): def test_raises_exception_if_one_element_is_not_a_dict(self, mock_parse): mock_parse.return_value = [{"order": 0}, "not a dict", {"order": 1}] with pytest.raises(CriticalInputError, match=r"not a dict"): - _, _ = self.object.get_next(self.timeout) - _, _ = self.object.get_next(self.timeout) - _, _ = self.object.get_next(self.timeout) + _ = self.object.get_next(self.timeout) + _ = self.object.get_next(self.timeout) + _ = self.object.get_next(self.timeout) @mock.patch(parse_function) def test_repeat_documents_repeats_documents(self, mock_parse): config = copy.deepcopy(self.CONFIG) config["repeat_documents"] = True mock_parse.return_value = [{"order": 0}, {"order": 1}, {"order": 2}] - object = Factory.create(configuration={"Test Instance Name": config}) + connector = Factory.create(configuration={"Test Instance Name": config}) for order in range(0, 9): - event, _ = object.get_next(self.timeout) + event = connector.get_next(self.timeout) assert event.get("order") == order % 3 @pytest.mark.skip(reason="not implemented") diff --git a/tests/unit/connector/test_jsonl_input.py b/tests/unit/connector/test_jsonl_input.py index a8e3a234f..ff0f1551a 100644 --- a/tests/unit/connector/test_jsonl_input.py +++ b/tests/unit/connector/test_jsonl_input.py @@ -28,14 +28,14 @@ def test_documents_returns(self, mock_parse): def test_get_next_returns_document(self, mock_parse): mock_parse.return_value = [{"message": "test_message"}] expected = {"message": "test_message"} - document, _ = self.object.get_next(self.timeout) + document = self.object.get_next(self.timeout) assert document == expected @mock.patch(parse_function) def test_get_next_returns_multiple_documents(self, mock_parse): mock_parse.return_value = [{"order": 0}, {"order": 1}] - assert ({"order": 0}, None) == self.object.get_next(self.timeout) - assert ({"order": 1}, None) == self.object.get_next(self.timeout) + assert {"order": 0} == self.object.get_next(self.timeout) + assert {"order": 1} == self.object.get_next(self.timeout) @mock.patch(parse_function) def test_raises_exception_if_not_a_dict(self, mock_parse): @@ -59,7 +59,7 @@ def test_repeat_documents_repeats_documents(self, mock_parse): object = Factory.create(configuration={"Test Instance Name": config}) for order in range(0, 9): - event, _ = object.get_next(self.timeout) + event = object.get_next(self.timeout) assert event.get("order") == order % 3 @pytest.mark.skip(reason="not implemented") diff --git a/tests/unit/connector/test_jsonl_output.py b/tests/unit/connector/test_jsonl_output.py index 20a659193..b23367980 100644 --- a/tests/unit/connector/test_jsonl_output.py +++ b/tests/unit/connector/test_jsonl_output.py @@ -15,7 +15,6 @@ class TestJsonlOutputOutput(BaseOutputTestCase): "type": "jsonl_output", "output_file": f"{tempfile.gettempdir()}/output.jsonl", "output_file_custom": f"{tempfile.gettempdir()}/custom_file", - "output_file_error": f"{tempfile.gettempdir()}/error_file", } def setup_method(self) -> None: @@ -43,16 +42,6 @@ def test_store_maintains_order_of_documents(self, _): for order in range(0, 3): assert self.object.events[order]["order"] == order - @mock.patch("logprep.connector.jsonl.output.JsonlOutput._write_json") - def test_stores_failed_events_in_respective_list(self, _): - self.object.store_failed("message", {"doc": "received"}, {"doc": "processed"}) - assert len(self.object.failed_events) == 1 - assert self.object.failed_events[0] == ( - "message", - {"doc": "received"}, - {"doc": "processed"}, - ) - @mock.patch("logprep.connector.jsonl.output.JsonlOutput._write_json") def test_write_document_to_file_on_store(self, _): self.object.store(self.document) @@ -75,18 +64,6 @@ def test_write_multiple_documents_to_file_on_store(self, _): mock.call("/tmp/output.jsonl", {"message": "test message"}), ] - @mock.patch("logprep.connector.jsonl.output.JsonlOutput._write_json") - def test_store_failed_writes_errors(self, _): - self.object.store_failed("my error message", self.document, self.document) - self.object._write_json.assert_called_with( - f"{tempfile.gettempdir()}/error_file", - { - "error_message": "my error message", - "document_received": {"message": "test message"}, - "document_processed": {"message": "test message"}, - }, - ) - @mock.patch("builtins.open") def test_write_json_writes_to_file(self, mock_open): JsonlOutput._write_json("the/file/path", self.document) @@ -96,7 +73,6 @@ def test_write_json_writes_to_file(self, mock_open): def test_setup_creates_single_file_if_only_output_file(self, mock_open): config = copy.deepcopy(self.CONFIG) config["output_file_custom"] = "" - config["output_file_error"] = "" self.object = Factory.create({"Test Instance Name": config}) self.object.setup() mock_open.assert_called() @@ -108,12 +84,6 @@ def test_store_counts_processed_events(self, _): # pylint: disable=arguments-di self.object.store({"message": "my event message"}) assert self.object.metrics.number_of_processed_events == 1 - @mock.patch("builtins.open") - def test_store_calls_batch_finished_callback(self, _): # pylint: disable=arguments-differ - self.object.input_connector = mock.MagicMock() - self.object.store({"message": "my event message"}) - self.object.input_connector.batch_finished_callback.assert_called() - @mock.patch("builtins.open") def test_store_calls_batch_finished_callback_without_errors( self, _ diff --git a/tests/unit/connector/test_opensearch_output.py b/tests/unit/connector/test_opensearch_output.py index 78bb6713c..ab9836042 100644 --- a/tests/unit/connector/test_opensearch_output.py +++ b/tests/unit/connector/test_opensearch_output.py @@ -10,8 +10,6 @@ import re import time import uuid -from datetime import datetime -from math import isclose from unittest import mock import opensearchpy as search @@ -20,7 +18,7 @@ from opensearchpy import helpers from logprep.abc.component import Component -from logprep.abc.output import FatalOutputError +from logprep.abc.output import CriticalOutputError, FatalOutputError from logprep.connector.opensearch.output import OpensearchOutput from logprep.factory import Factory from logprep.util.time import TimeParser @@ -42,7 +40,6 @@ class TestOpenSearchOutput(BaseOutputTestCase): "type": "opensearch_output", "hosts": ["localhost:9200"], "default_index": "default_index", - "error_index": "error_index", "message_backlog_size": 1, "timeout": 5000, } @@ -58,311 +55,23 @@ def test_store_sends_to_default_index(self): config["message_backlog_size"] = 2 self.object = Factory.create({"opensearch_output": config}) event = {"field": "content"} - expected = { - "_index": "default_index", - "message": '{"field": "content"}', - "reason": "Missing index in document", - } - self.object.store(event) - - assert self.object._message_backlog[0].pop("@timestamp") - assert self.object._message_backlog[0] == expected - - def test_store_sends_event_to_expected_index_with_date_pattern_if_index_missing_in_event(self): - default_index = "default_index-%{%y-%m-%d}" - event = {"field": "content"} - formatted_date = TimeParser.now().strftime("%y-%m-%d") - expected_index = re.sub(r"%{%y-%m-%d}", formatted_date, default_index) - expected = { - "_index": expected_index, - "message": '{"field": "content"}', - "reason": "Missing index in document", - } - config = copy.deepcopy(self.CONFIG) - config["default_index"] = default_index - config["message_backlog_size"] = 2 - self.object = Factory.create({"opensearch_output": config}) self.object.store(event) - assert self.object._message_backlog[0].pop("@timestamp") - assert self.object._message_backlog[0] == expected + assert self.object._message_backlog[0] == event + assert self.object._message_backlog[0].get("_index") == config.get("default_index") def test_store_custom_sends_event_to_expected_index(self): custom_index = "custom_index" event = {"field": "content"} - expected = {"field": "content", "_index": custom_index} + expected = {"field": "content", "_index": custom_index, "_op_type": "index"} config = copy.deepcopy(self.CONFIG) config["message_backlog_size"] = 2 self.object = Factory.create({"opensearch_output": config}) self.object.store_custom(event, custom_index) assert self.object._message_backlog[0] == expected - def test_store_failed(self): - error_index = "error_index" - event_received = {"field": "received"} - event = {"field": "content"} - error_message = "error message" - expected = { - "error": error_message, - "original": event_received, - "processed": event, - "_index": error_index, - "@timestamp": str(datetime.now()), - } - - config = copy.deepcopy(self.CONFIG) - config["message_backlog_size"] = 2 - self.object = Factory.create({"opensearch_output": config}) - self.object.store_failed(error_message, event_received, event) - - error_document = self.object._message_backlog[0] - # timestamp is compared to be approximately the same, - # since it is variable and then removed to compare the rest - error_time = datetime.timestamp(TimeParser.from_string(error_document["@timestamp"])) - expected_time = datetime.timestamp(TimeParser.from_string(error_document["@timestamp"])) - assert isclose(error_time, expected_time) - del error_document["@timestamp"] - del expected["@timestamp"] - - assert error_document == expected - - def test_create_es_output_settings_contains_expected_values(self): - expected = { - "reason": "A reason for failed indexing", - "_index": "default_index", - } - failed_document = self.object._build_failed_index_document( - {"invalid_json": NotJsonSerializableMock(), "something_valid": "im_valid!"}, - "A reason for failed indexing", - ) - assert "NotJsonSerializableMock" in failed_document.pop("message") - assert failed_document.pop("@timestamp") - assert failed_document == expected - - def test_build_failed_index_document(self): - expected = { - "reason": "A reason for failed indexing", - "message": '{"foo": "bar"}', - "_index": "default_index", - } - failed_document = self.object._build_failed_index_document( - {"foo": "bar"}, "A reason for failed indexing" - ) - assert failed_document.pop("@timestamp") - assert failed_document == expected - - @mock.patch( - "opensearchpy.helpers.parallel_bulk", - side_effect=search.SerializationError, - ) - def test_write_to_search_context_calls_handle_serialization_error_if_serialization_error( - self, _ - ): - config = copy.deepcopy(self.CONFIG) - config["message_backlog_size"] = 1 - self.object = Factory.create({"opensearch_output": config}) - self.object._handle_serialization_error = mock.MagicMock() - self.object._message_backlog.append({"dummy": "event"}) - self.object._write_to_search_context() - self.object._handle_serialization_error.assert_called() - - @mock.patch( - "opensearchpy.helpers.parallel_bulk", - side_effect=search.ConnectionError(-1), - ) - @mock.patch("time.sleep", mock.MagicMock()) # to speed up test execution - def test_write_to_search_context_calls_handle_connection_error_if_connection_error(self, _): - config = copy.deepcopy(self.CONFIG) - config["message_backlog_size"] = 1 - self.object = Factory.create({"opensearch_output": config}) - self.object._handle_connection_error = mock.MagicMock() - self.object._message_backlog.append({"dummy": "event"}) - self.object._write_to_search_context() - self.object._handle_connection_error.assert_called() - - @mock.patch( - "opensearchpy.helpers.parallel_bulk", - side_effect=helpers.BulkIndexError, - ) - def test_write_to_search_context_calls_handle_bulk_index_error_if_bulk_index_error(self, _): - config = copy.deepcopy(self.CONFIG) - config["message_backlog_size"] = 1 - self.object = Factory.create({"opensearch_output": config}) - self.object._handle_bulk_index_error = mock.MagicMock() - self.object._message_backlog.append({"dummy": "event"}) - self.object._write_to_search_context() - self.object._handle_bulk_index_error.assert_called() - - @mock.patch("opensearchpy.helpers.parallel_bulk") - def test__handle_bulk_index_error_calls_bulk(self, fake_bulk): - mock_bulk_index_error = mock.MagicMock() - mock_bulk_index_error.errors = [ - { - "index": { - "data": {"my": "document"}, - "error": {"type": "myerrortype", "reason": "myreason"}, - } - } - ] - self.object._handle_bulk_index_error(mock_bulk_index_error) - fake_bulk.assert_called() - - @mock.patch("opensearchpy.helpers.parallel_bulk") - def test_handle_bulk_index_error_calls_bulk_with_error_documents(self, fake_bulk): - mock_bulk_index_error = mock.MagicMock() - mock_bulk_index_error.errors = [ - { - "index": { - "data": {"my": "document"}, - "error": {"type": "myerrortype", "reason": "myreason"}, - } - } - ] - self.object._handle_bulk_index_error(mock_bulk_index_error) - error_document = fake_bulk.call_args.kwargs.get("actions").pop() - assert "reason" in error_document - assert "@timestamp" in error_document - assert "_index" in error_document - assert "message" in error_document - assert error_document.get("reason") == "myerrortype: myreason" - assert error_document.get("message") == json.dumps({"my": "document"}) - - @pytest.mark.parametrize( - "status_code, error, error_info, messages, discarded_cnt, exception", - [ - ( - 429, - "circuit_breaking_exception", - {"anything": "anything"}, - [{"foo": "*" * 500}], - 1, - None, - ), - ( - 429, - "circuit_breaking_exception", - {"anything": "anything"}, - [{"foo": "bar"}, {"bar": "baz"}], - 0, - FatalOutputError, - ), - ( - 429, - "circuit_breaking_exception", - {"anything": "anything"}, - [{"foo": "*" * 500}, {"bar": "baz"}], - 1, - None, - ), - ( - 429, - "circuit_breaking_exception", - {"anything": "anything"}, - [{"foo": "*" * 500}, {"bar": "*" * 500}], - 2, - None, - ), - ( - 123, - "circuit_breaking_exception", - {"anything": "anything"}, - [{"foo": "*" * 500}], - 1, - FatalOutputError, - ), - ( - 429, - "wrong_exception", - {"anything": "anything"}, - [{"foo": "*" * 500}], - 1, - FatalOutputError, - ), - ( - 429, - "rejected_execution_exception", - {"invalid": "error"}, - [{"foo": "*" * 500}], - 1, - FatalOutputError, - ), - ( - 429, - "rejected_execution_exception", - {"error": {"reason": "wrong_reason"}}, - [{"foo": "*" * 500}], - 1, - FatalOutputError, - ), - ( - 429, - "rejected_execution_exception", - { - "error": { - "reason": "... " - "coordinating_operation_bytes=9, max_coordinating_and_primary_bytes=1 " - "..." - } - }, - [{"foo": "*" * 500}], - 1, - None, - ), - ( - 429, - "rejected_execution_exception", - { - "error": { - "reason": "... " - "coordinating_operation_bytes=1, max_coordinating_and_primary_bytes=9 " - "..." - } - }, - [{"foo": "*" * 500}], - 1, - FatalOutputError, - ), - ], - ) - def test_handle_transport_error_calls_bulk_with_error_documents( - self, status_code, error, error_info, messages, discarded_cnt, exception - ): - config = copy.deepcopy(self.CONFIG) - config["maximum_message_size_mb"] = 5 * 10**-4 - self.object = Factory.create({"opensearch_output": config}) - mock_transport_error = search.exceptions.TransportError(status_code, error, error_info) - - if exception: - with pytest.raises(exception): - self.object._handle_transport_error(mock_transport_error) - else: - self.object._message_backlog = messages - self.object._handle_transport_error(mock_transport_error) - above_limit = [] - under_limit = [] - for message in self.object._message_backlog: - if message.get("_index") == "error_index": - assert message.get("error", "").startswith( - "Discarded message that is larger than the allowed size limit" - ) - assert len(message.get("processed_snipped", "")) <= 1000 - assert message.get("processed_snipped", "").endswith(" ...") - above_limit.append(message) - else: - under_limit.append(message) - assert len(above_limit) == discarded_cnt - assert len(above_limit) + len(under_limit) == len(self.object._message_backlog) - - def test_handle_connection_error_raises_fatal_output_error(self): - with pytest.raises(FatalOutputError): - self.object._handle_connection_error(mock.MagicMock()) - - def test_handle_serialization_error_raises_fatal_output_error(self): - with pytest.raises(FatalOutputError): - self.object._handle_serialization_error(mock.MagicMock()) - - def test_setup_registers_flush_timout_tasks(self): + def test_setup_registers_flush_timeout_tasks(self): job_count = len(Component._scheduler.jobs) with mock.patch.object(self.object, "_search_context", new=mock.MagicMock()): self.object.setup() @@ -386,30 +95,6 @@ def test_message_backlog_is_cleared_after_it_was_written(self): self.object.store({"event": "test_event"}) assert len(self.object._message_backlog) == 0 - @pytest.mark.skip(reason="This test is only for local debugging") - def test_opensearch_parallel_bulk(self): - config = { - "type": "opensearch_output", - "hosts": ["localhost:9200"], - "default_index": "default_index", - "error_index": "error_index", - "message_backlog_size": 1, - "timeout": 5000, - } - output: OpensearchOutput = Factory.create({"opensearch_output": config}) - uuid_str = str(uuid.uuid4()) - result = output._search_context.search( - index="defaultindex", body={"query": {"match": {"foo": uuid_str}}} - ) - len_before = len(result["hits"]["hits"]) - output._message_backlog = [{"foo": uuid_str, "_index": "defaultindex"}] - output._write_backlog() - time.sleep(1) - result = output._search_context.search( - index="defaultindex", body={"query": {"match": {"foo": uuid_str}}} - ) - assert len(result["hits"]["hits"]) > len_before - @mock.patch( "logprep.connector.opensearch.output.OpensearchOutput._search_context", new=mock.MagicMock(), @@ -419,41 +104,6 @@ def test_setup_populates_cached_properties(self, mock_getmembers): self.object.setup() mock_getmembers.assert_called_with(self.object) - @mock.patch( - "opensearchpy.helpers.parallel_bulk", - side_effect=search.TransportError(429, "rejected_execution_exception", {}), - ) - @mock.patch("time.sleep") - def test_write_backlog_fails_if_all_retries_are_exceeded(self, _, mock_sleep): - config = copy.deepcopy(self.CONFIG) - config["maximum_message_size_mb"] = 1 - config["max_retries"] = 5 - self.object = Factory.create({"opensearch_output": config}) - self.object._message_backlog = [{"some": "event"}] - with pytest.raises( - FatalOutputError, match="Opensearch too many requests, all parallel bulk retries failed" - ): - self.object._write_backlog() - assert mock_sleep.call_count == 6 # one initial try + 5 retries - assert self.object._message_backlog == [{"some": "event"}] - - @mock.patch("time.sleep") - def test_write_backlog_is_successful_after_two_retries(self, mock_sleep): - side_effects = [ - search.TransportError(429, "rejected_execution_exception", {}), - search.TransportError(429, "rejected_execution_exception", {}), - [], - ] - with mock.patch("opensearchpy.helpers.parallel_bulk", side_effect=side_effects): - config = copy.deepcopy(self.CONFIG) - config["maximum_message_size_mb"] = 1 - config["max_retries"] = 5 - self.object = Factory.create({"opensearch_output": config}) - self.object._message_backlog = [{"some": "event"}] - self.object._write_backlog() - assert mock_sleep.call_count == 2 - assert self.object._message_backlog == [] - def test_health_returns_true_on_success(self): self.object._search_context = mock.MagicMock() self.object._search_context.cluster.health.return_value = {"status": "green"} @@ -483,3 +133,43 @@ def test_health_returns_false_on_cluster_status_not_green(self): self.object._search_context = mock.MagicMock() self.object._search_context.cluster.health.return_value = {"status": "yellow"} assert not self.object.health() + + def test_write_backlog_clears_message_backlog_on_success(self): + self.object._message_backlog = [{"some": "event"}] + self.object._write_backlog() + assert len(self.object._message_backlog) == 0, "Message backlog should be cleared" + + def test_write_backlog_clears_message_backlog_on_failure(self): + self.object._message_backlog = [{"some": "event"}] + self.object._bulk = mock.MagicMock( + side_effect=CriticalOutputError(mock.MagicMock(), "", "") + ) + with pytest.raises(CriticalOutputError): + self.object._write_backlog() + assert len(self.object._message_backlog) == 0, "Message backlog should be cleared" + + def test_write_backlog_clears_failed_on_success(self): + self.object._message_backlog = [{"some": "event"}] + self.object._failed = [{"some": "event"}] + with mock.patch("logprep.connector.opensearch.output.OpensearchOutput._bulk"): + self.object._write_backlog() + assert len(self.object._failed) == 0, "temporary failed backlog should be cleared" + + def test_write_backlog_clears_failed_on_failure(self): + self.object._message_backlog = [{"some": "event"}] + self.object._failed = [{"some": "event"}] + with pytest.raises(CriticalOutputError): + self.object._write_backlog() + assert len(self.object._failed) == 0, "temporary failed backlog should be cleared" + + def test_write_backlog_creates_failed_event(self): + error_message = "test error" + event = {"some": "event"} + helpers.parallel_bulk = mock.MagicMock( + return_value=[(False, {"index": {"error": error_message}})] + ) + self.object._message_backlog = [event] + with pytest.raises(CriticalOutputError) as error: + self.object._write_backlog() + assert error.value.message == "failed to index" + assert error.value.raw_input == [{"errors": error_message, "event": event}] diff --git a/tests/unit/connector/test_real_kafka.py b/tests/unit/connector/test_real_kafka.py index 404816593..df0aa208e 100644 --- a/tests/unit/connector/test_real_kafka.py +++ b/tests/unit/connector/test_real_kafka.py @@ -30,34 +30,27 @@ def setup_module(): @pytest.mark.skipif(in_ci, reason="requires kafka") class TestKafkaConnection: def get_topic_partition_size(self, topic_partition: TopicPartition) -> int: - time.sleep(1) # nosemgrep + time.sleep(1) consumer = Consumer(kafka_config | {"group.id": str(uuid.uuid4())}) lowwater, highwater = consumer.get_watermark_offsets(topic_partition) consumer.close() return highwater - lowwater def wait_for_topic_creation(self): - while ( - self.topic_name not in self.admin.list_topics().topics - and self.error_topic_name not in self.admin.list_topics().topics - ): - time.sleep(2) # nosemgrep + while self.topic_name not in self.admin.list_topics().topics: + time.sleep(2) def setup_method(self): self.admin = AdminClient(kafka_config) self.topic_name = str(uuid.uuid4()) self.topic = NewTopic(self.topic_name, num_partitions=1, replication_factor=1) self.topic_partition = TopicPartition(self.topic_name, 0) - self.error_topic_name = str(uuid.uuid4()) - self.error_topic = NewTopic(self.error_topic_name, num_partitions=1, replication_factor=1) - self.error_topic_partition = TopicPartition(self.topic_name, 0) - self.admin.create_topics([self.topic, self.error_topic]) + self.admin.create_topics([self.topic]) self.wait_for_topic_creation() ouput_config = { "type": "confluentkafka_output", "topic": self.topic_name, - "error_topic": self.error_topic_name, "flush_timeout": 1, "kafka_config": { "bootstrap.servers": "localhost:9092", diff --git a/tests/unit/connector/test_s3_output.py b/tests/unit/connector/test_s3_output.py index 58b54949d..fd62e3509 100644 --- a/tests/unit/connector/test_s3_output.py +++ b/tests/unit/connector/test_s3_output.py @@ -43,7 +43,6 @@ class TestS3Output(BaseOutputTestCase): expected_metrics = [ "logprep_processing_time_per_event", "logprep_number_of_processed_events", - "logprep_number_of_failed_events", "logprep_number_of_warnings", "logprep_number_of_errors", "logprep_number_of_successful_writes", @@ -114,35 +113,6 @@ def test_store_custom_writes_event_with_expected_prefix(self, base_prefix): s3_output.store_custom(event, custom_prefix) assert s3_output._message_backlog[custom_prefix][0] == expected - @pytest.mark.parametrize("base_prefix", base_prefix_tests_cases) - def test_store_failed(self, base_prefix): - error_prefix = f"{base_prefix}/error_prefix" if base_prefix else "error_prefix" - event_received = {"field": "received"} - event = {"field": "content"} - error_message = "error message" - expected = { - "error": error_message, - "original": event_received, - "processed": event, - "@timestamp": str(datetime.now()), - } - s3_config = deepcopy(self.CONFIG) - s3_config.update({"error_prefix": error_prefix, "message_backlog_size": 2}) - s3_output = Factory.create({"s3": s3_config}) - - s3_output.store_failed(error_message, event_received, event) - - error_document = s3_output._message_backlog[error_prefix][0] - # timestamp is compared to be approximately the same, - # since it is variable and then removed to compare the rest - error_time = datetime.timestamp(TimeParser.from_string(error_document["@timestamp"])) - expected_time = datetime.timestamp(TimeParser.from_string(error_document["@timestamp"])) - assert isclose(error_time, expected_time) - del error_document["@timestamp"] - del expected["@timestamp"] - - assert error_document == expected - def test_create_s3_building_prefix_with_invalid_json(self): expected = {"reason": "A reason for failed prefix"} failed_document = self.object._build_no_prefix_document( @@ -234,12 +204,6 @@ def test_store_counts_processed_events(self): self.object._s3_resource = mock.MagicMock() super().test_store_counts_processed_events() - def test_store_calls_batch_finished_callback(self): - self.object._s3_resource = mock.MagicMock() - self.object.input_connector = mock.MagicMock() - self.object.store({"message": "my event message"}) - self.object.input_connector.batch_finished_callback.assert_called() - def test_store_does_not_call_batch_finished_callback_if_disabled(self): s3_config = deepcopy(self.CONFIG) s3_config.update({"call_input_callback": False}) @@ -276,10 +240,6 @@ def test_write_backlog_executed_on_empty_message_backlog(self): self.object._write_backlog() mock_backlog_size.assert_not_called() - def test_store_failed_counts_failed_events(self): - self.object._write_backlog = mock.MagicMock() - super().test_store_failed_counts_failed_events() - def test_setup_registers_flush_timeout_tasks(self): job_count = len(self.object._scheduler.jobs) with pytest.raises(FatalOutputError): diff --git a/tests/unit/exceptions/test_connector_exceptions.py b/tests/unit/exceptions/test_connector_exceptions.py index a2a77707f..a207f7d39 100644 --- a/tests/unit/exceptions/test_connector_exceptions.py +++ b/tests/unit/exceptions/test_connector_exceptions.py @@ -44,6 +44,20 @@ def setup_method(self): self.object = Factory.create({"test connector": {"type": "dummy_output", "default": False}}) self.exception_args = (self.object, "the error message", b"raw input") + def test_init_copies_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_output", "default": False}}) + raw_input = {"key": "value"} + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + + def test_init_deepcopy_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_output", "default": False}}) + raw_input = [{"key": "value"}, {"key": {"key": "value"}}] + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + class TestOutputError(ExceptionBaseTest): exception = OutputError @@ -92,6 +106,20 @@ def setup_method(self): self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) self.exception_args = (self.object, "the error message", b"raw input") + def test_init_copies_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) + raw_input = {"key": "value"} + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + + def test_init_deepcopy_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) + raw_input = [{"key": "value"}, {"key": {"key": "value"}}] + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + class TestCriticalInputParsingError(ExceptionBaseTest): exception = CriticalInputParsingError @@ -104,6 +132,20 @@ def setup_method(self): self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) self.exception_args = (self.object, "the error message", b"raw input") + def test_init_copies_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) + raw_input = {"key": "value"} + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + + def test_init_deepcopy_raw_input(self): + self.object = Factory.create({"test connector": {"type": "dummy_input", "documents": []}}) + raw_input = [{"key": "value"}, {"key": {"key": "value"}}] + exception = self.exception(self.object, "the error message", raw_input) + assert exception.raw_input == raw_input + assert exception.raw_input is not raw_input + class TestFatalInputError(ExceptionBaseTest): exception = FatalInputError diff --git a/tests/unit/exceptions/test_processing_exceptions.py b/tests/unit/exceptions/test_processing_exceptions.py index ce7473ff4..52c8534b6 100644 --- a/tests/unit/exceptions/test_processing_exceptions.py +++ b/tests/unit/exceptions/test_processing_exceptions.py @@ -23,7 +23,7 @@ class TestProcessingWarning(ExceptionBaseTest): counted_metric_name = "number_of_warnings" -class TestFieldExsitsWarning(ExceptionBaseTest): +class TestFieldExistsWarning(ExceptionBaseTest): exception = FieldExistsWarning error_message = ( r"FieldExistsWarning: The following fields could not be written," @@ -42,13 +42,17 @@ class TestProcessingCriticalError(ExceptionBaseTest): exception = ProcessingCriticalError error_message = ( - r"ProcessingCriticalError: the error message ->" - r" event was send to error output and further processing stopped, " - r"rule.id='.+', rule.description='', event=\{'message': 'test_event'\}" + r"ProcessingCriticalError: 'the error message' -> " + r"rule.id: '.*' -> " + r"event was send to error output and further processing stopped" ) counted_metric_name = "number_of_errors" + def setup_method(self): + super().setup_method() + self.exception_args = ("the error message", self.object) + class TestProcessingError(ExceptionBaseTest): exception = ProcessingError diff --git a/tests/unit/framework/test_pipeline.py b/tests/unit/framework/test_pipeline.py index 70f6b944b..3dec94242 100644 --- a/tests/unit/framework/test_pipeline.py +++ b/tests/unit/framework/test_pipeline.py @@ -1,12 +1,10 @@ # pylint: disable=missing-docstring # pylint: disable=protected-access # pylint: disable=attribute-defined-outside-init -import logging import multiprocessing +import queue from copy import deepcopy -from logging import DEBUG -from multiprocessing import Lock -from typing import Iterable, Tuple +from typing import Tuple from unittest import mock import pytest @@ -17,6 +15,7 @@ CriticalInputError, CriticalInputParsingError, FatalInputError, + Input, InputWarning, ) from logprep.abc.output import ( @@ -25,7 +24,7 @@ Output, OutputWarning, ) -from logprep.abc.processor import ProcessorResult +from logprep.abc.processor import Processor, ProcessorResult from logprep.factory import Factory from logprep.framework.pipeline import Pipeline, PipelineResult from logprep.processor.base.exceptions import ( @@ -33,7 +32,6 @@ ProcessingCriticalError, ProcessingWarning, ) -from logprep.processor.deleter.rule import DeleterRule from logprep.util.configuration import Configuration original_create = Factory.create @@ -51,6 +49,7 @@ class ConfigurationForTests: {"mock_processor2": {"proc": "conf"}}, ], "metrics": {"enabled": False}, + "error_output": {"dummy": {"type": "dummy_output"}}, } ) @@ -60,12 +59,42 @@ def get_mock_create(): Create a new mock_create magic mock with a default processor result. Is applied for every test. """ - mock_create = mock.MagicMock() - mock_component = mock.MagicMock() - mock_component.process = mock.MagicMock() - mock_component.process.return_value = ProcessorResult(processor_name="mock_processor") - mock_create.return_value = mock_component - return mock_create + + def create_component(config): + _, config = config.popitem() + component = None + match config: + case {"type": component_type} if "input" in component_type: + component = mock.create_autospec(spec=Input) + case {"type": component_type} if "output" in component_type: + component = mock.create_autospec(spec=Output) + case {"type": component_type} if "processor_with_errors" in component_type: + component = mock.create_autospec(spec=Processor) + processor_result = mock.create_autospec(spec=ProcessorResult) + rule = mock.MagicMock() + rule.id = "test_rule_id" + error = ProcessingCriticalError("this is a processing critical error", rule) + processor_result.errors = [error] + component.process.return_value = processor_result + case {"type": component_type} if "processor_with_warnings" in component_type: + component = mock.create_autospec(spec=Processor) + processor_result = mock.create_autospec(spec=ProcessorResult) + processor_result.warnings = [mock.MagicMock(), mock.MagicMock()] + component.process.return_value = processor_result + case _: + component = mock.create_autospec(spec=Processor) + component.process.return_value = mock.create_autospec(spec=ProcessorResult) + component.metrics = mock.MagicMock() + component._called_config = config + return component + + return create_component + + +@pytest.fixture(name="mock_processor") +def get_mock_processor(): + mock_create = get_mock_create() + return mock_create({"mock_processor": {"type": "mock_processor"}}) @mock.patch("logprep.factory.Factory.create", new_callable=get_mock_create) @@ -75,13 +104,15 @@ def setup_method(self): self.pipeline = Pipeline( pipeline_index=1, - config=self.logprep_config, + config=deepcopy(self.logprep_config), + error_queue=queue.Queue(), ) - def test_pipeline_property_returns_pipeline(self, mock_create): + def test_pipeline_property_returns_pipeline(self, _): self.pipeline._setup() assert len(self.pipeline._pipeline) == 2 - assert mock_create.call_count == 4 # 2 processors, 1 input, 1 output + assert isinstance(self.pipeline._pipeline[0], Processor) + assert isinstance(self.pipeline._pipeline[1], Processor) def test_setup_calls_setup_on_pipeline_processors(self, _): self.pipeline._setup() @@ -104,54 +135,29 @@ def test_setup_calls_setup_on_input_and_output(self, _): def test_passes_timeout_parameter_to_inputs_get_next(self, _): self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({}, {}) + self.pipeline._input.get_next.return_value = {} self.pipeline.process_pipeline() timeout = self.logprep_config.timeout self.pipeline._input.get_next.assert_called_with(timeout) - def test_empty_documents_are_not_forwarded_to_other_processors(self, _): - input_data = [{"do_not_delete": "1"}, {"delete_me": "2"}, {"do_not_delete": "3"}] - connector_config = {"dummy": {"type": "dummy_input", "documents": input_data}} - input_connector = original_create(connector_config) - self.pipeline._input = input_connector - self.pipeline._output = { - "dummy": original_create({"dummy": {"type": "dummy_output"}}), - } - deleter_config = { - "deleter processor": { - "type": "deleter", - "specific_rules": [], - "generic_rules": [], - } - } - deleter_processor = original_create(deleter_config) - deleter_rule = DeleterRule._create_from_dict( - {"filter": "delete_me", "deleter": {"delete": True}} - ) - deleter_processor._specific_tree.add_rule(deleter_rule) - processor_with_mock_result = mock.MagicMock() - processor_with_mock_result.process = mock.MagicMock() - processor_with_mock_result.process.return_value = ProcessorResult( - processor_name="processor_with_mock_res" - ) - self.pipeline._pipeline = [ - processor_with_mock_result, - deleter_processor, - deepcopy(processor_with_mock_result), - ] - logger = logging.getLogger("Pipeline") - logger.setLevel(DEBUG) - while self.pipeline._input._documents: - self.pipeline.process_pipeline() - assert len(self.pipeline._input._documents) == 0, "all events were processed" - assert self.pipeline._pipeline[0].process.call_count == 3, "called for all events" - assert self.pipeline._pipeline[2].process.call_count == 2, "not called for deleted event" - assert {"delete_me": "2"} not in self.pipeline._output["dummy"].events - assert len(self.pipeline._output["dummy"].events) == 2 + def test_empty_documents_are_not_forwarded_to_other_processors(self, _, mock_processor): + def delete_event(event) -> ProcessorResult: + event.clear() + return ProcessorResult(processor_name="deleter", event=event) + + mock_deleter = mock.create_autospec(spec=Processor) + mock_deleter.process = delete_event + last_processor = mock.create_autospec(spec=Processor) + pipeline = [mock_processor, mock_deleter, last_processor] + event = {"delete_me": "1"} + _ = PipelineResult(event=event, pipeline=pipeline) + mock_processor.process.assert_called() + last_processor.process.assert_not_called() + assert not event, "event was deleted" - def test_not_empty_documents_are_stored_in_the_output(self, _): + def test_documents_are_stored_in_the_output(self, _): self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"message": "test"}, None) + self.pipeline._input.get_next.return_value = {"message": "test"} self.pipeline._store_event = mock.MagicMock() self.pipeline.process_pipeline() assert self.pipeline._store_event.call_count == 1 @@ -159,13 +165,11 @@ def test_not_empty_documents_are_stored_in_the_output(self, _): def test_empty_documents_are_not_stored_in_the_output(self, _): def mock_process_event(event): event.clear() - return PipelineResult( - event=event, event_received=event, results=[], pipeline=self.pipeline._pipeline - ) + return PipelineResult(event=event, pipeline=self.pipeline._pipeline) self.pipeline.process_event = mock_process_event self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"message": "test"}, None) + self.pipeline._input.get_next.return_value = {"message": "test"} self.pipeline._store_event = mock.MagicMock() self.pipeline.process_pipeline() assert self.pipeline._store_event.call_count == 0 @@ -193,15 +197,19 @@ def test_all_events_provided_by_input_arrive_at_output(self, _): assert self.pipeline._output["dummy"].events == expected_output_data @mock.patch("logging.Logger.error") - def test_critical_output_error_is_logged_and_stored_as_failed(self, mock_error, _): + def test_critical_output_error_is_logged_and_event_is_stored_to_error_queue( + self, mock_error, _ + ): + self.pipeline.enqueue_error = mock.MagicMock() self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"order": 1}, None) + self.pipeline._input.get_next.return_value = {"order": 1} + failed_event = {"failed": "event"} raised_error = CriticalOutputError( - self.pipeline._output["dummy"], "An error message", {"failed": "event"} + self.pipeline._output["dummy"], "An error message", failed_event ) self.pipeline._output["dummy"].store.side_effect = raised_error self.pipeline.process_pipeline() - self.pipeline._output["dummy"].store_failed.assert_called() + self.pipeline.enqueue_error.assert_called_with(raised_error) mock_error.assert_called_with(str(raised_error)) @mock.patch("logging.Logger.warning") @@ -213,7 +221,7 @@ def raise_warning_error(_): self.pipeline._input.metrics = mock.MagicMock() self.pipeline._input.metrics.number_of_warnings = 0 - self.pipeline._input.get_next.return_value = ({"order": 1}, None) + self.pipeline._input.get_next.return_value = {"order": 1} self.pipeline.process_pipeline() self.pipeline._input.get_next.side_effect = raise_warning_error self.pipeline.process_pipeline() @@ -226,7 +234,7 @@ def raise_warning_error(_): @mock.patch("logging.Logger.warning") def test_output_warning_error_is_logged_but_processing_continues(self, mock_warning, _): self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"order": 1}, None) + self.pipeline._input.get_next.return_value = {"order": 1} self.pipeline._output["dummy"].metrics = mock.MagicMock() self.pipeline._output["dummy"].metrics.number_of_warnings = 0 self.pipeline.process_pipeline() @@ -243,64 +251,68 @@ def test_output_warning_error_is_logged_but_processing_continues(self, mock_warn @mock.patch("logging.Logger.warning") def test_processor_warning_error_is_logged_but_processing_continues(self, mock_warning, _): self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"message": "test"}, None) + self.pipeline._input.get_next.return_value = {"message": "test"} mock_rule = mock.MagicMock() processing_warning = ProcessingWarning("not so bad", mock_rule, {"message": "test"}) self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="mock_processor", warnings=[processing_warning] ) self.pipeline.process_pipeline() - self.pipeline._input.get_next.return_value = ({"message": "test"}, None) - result = self.pipeline.process_pipeline() - assert processing_warning in result.results[0].warnings + self.pipeline._input.get_next.return_value = {"message": "test"} + self.pipeline.process_pipeline() mock_warning.assert_called() assert "ProcessingWarning: not so bad" in mock_warning.call_args[0][0] assert self.pipeline._output["dummy"].store.call_count == 2, "all events are processed" @mock.patch("logging.Logger.error") - def test_processor_critical_error_is_logged_event_is_stored_in_error_output( + def test_processing_critical_error_is_logged_event_is_stored_in_error_output( self, mock_error, _ ): + self.pipeline.error_queue = queue.Queue() self.pipeline._setup() input_event1 = {"message": "first event"} input_event2 = {"message": "second event"} - self.pipeline._input.get_next.return_value = (input_event1, None) + self.pipeline._input.get_next.return_value = input_event1 mock_rule = mock.MagicMock() self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="", - errors=[ProcessingCriticalError("really bad things happened", mock_rule, input_event1)], + errors=[ProcessingCriticalError("really bad things happened", mock_rule)], ) self.pipeline.process_pipeline() - self.pipeline._input.get_next.return_value = (input_event2, None) + self.pipeline._input.get_next.return_value = input_event2 self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="", - errors=[ProcessingCriticalError("really bad things happened", mock_rule, input_event2)], + errors=[ProcessingCriticalError("really bad things happened", mock_rule)], ) self.pipeline.process_pipeline() assert self.pipeline._input.get_next.call_count == 2, "2 events gone into processing" assert mock_error.call_count == 2, f"two errors occurred: {mock_error.mock_calls}" - assert "ProcessingCriticalError: really bad things happened" in mock_error.call_args[0][0] + assert "ProcessingCriticalError: 'really bad things happened'" in mock_error.call_args[0][0] assert self.pipeline._output["dummy"].store.call_count == 0, "no event in output" - assert ( - self.pipeline._output["dummy"].store_failed.call_count == 2 - ), "errored events are gone to connector error output handler" + queued_item = self.pipeline.error_queue.get(0.01) + assert queued_item["event"] == str(input_event1), "first message was enqueued" + queued_item = self.pipeline.error_queue.get(0.01) + assert queued_item["event"] == str(input_event2), "second message was enqueued" @mock.patch("logging.Logger.error") @mock.patch("logging.Logger.warning") def test_processor_logs_processing_error_and_warnings_separately( - self, mock_warning, mock_error, _ + self, mock_warning, mock_error, mock_create ): self.pipeline._setup() input_event1 = {"message": "first event"} - self.pipeline._input.get_next.return_value = (input_event1, None) + self.pipeline._input.get_next.return_value = input_event1 mock_rule = mock.MagicMock() - self.pipeline._pipeline[1] = deepcopy(self.pipeline._pipeline[0]) + self.pipeline._pipeline = [ + mock_create({"mock_processor1": {"type": "mock_processor"}}), + mock_create({"mock_processor2": {"type": "mock_processor"}}), + ] warning = FieldExistsWarning(mock_rule, input_event1, ["foo"]) self.pipeline._pipeline[0].process.return_value = ProcessorResult( processor_name="", warnings=[warning] ) - error = ProcessingCriticalError("really bad things happened", mock_rule, input_event1) + error = ProcessingCriticalError("really bad things happened", mock_rule) self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="", errors=[error] ) @@ -314,23 +326,21 @@ def test_processor_logs_processing_error_and_warnings_separately( def test_critical_input_error_is_logged_error_is_stored_in_failed_events(self, mock_error, _): self.pipeline._setup() input_event = {"message": "test"} + raised_error = CriticalInputError(self.pipeline._input, "mock input error", input_event) def raise_critical(timeout): - raise CriticalInputError(self.pipeline._input, "mock input error", input_event) + raise raised_error self.pipeline._input.metrics = mock.MagicMock() self.pipeline._input.metrics.number_of_errors = 0 - self.pipeline._input.get_next.return_value = (input_event, None) + self.pipeline._input.get_next.return_value = input_event self.pipeline._input.get_next.side_effect = raise_critical + self.pipeline.enqueue_error = mock.MagicMock() self.pipeline.process_pipeline() self.pipeline._input.get_next.assert_called() - mock_error.assert_called_with( - str(CriticalInputError(self.pipeline._input, "mock input error", input_event)) - ) - assert self.pipeline._output["dummy"].store_failed.call_count == 1, "one error is stored" - self.pipeline._output["dummy"].store_failed.assert_called_with( - str(self.pipeline), input_event, {} - ) + mock_error.assert_called_with(str(raised_error)) + self.pipeline.enqueue_error.assert_called_with(raised_error) + assert self.pipeline.enqueue_error.call_count == 1, "one error is stored" assert self.pipeline._output["dummy"].store.call_count == 0, "no event is stored" @mock.patch("logging.Logger.warning") @@ -359,9 +369,10 @@ def raise_critical(event): dummy_output.metrics.number_of_errors = 0 self.pipeline._setup() self.pipeline._output["dummy"] = dummy_output - self.pipeline._input.get_next.return_value = (input_event, None) + self.pipeline._input.get_next.return_value = input_event + self.pipeline.enqueue_error = mock.MagicMock() self.pipeline.process_pipeline() - dummy_output.store_failed.assert_called() + self.pipeline.enqueue_error.assert_called() assert dummy_output.metrics.number_of_errors == 1, "counts error metric" mock_log_error.assert_called_with( str(CriticalOutputError(dummy_output, "mock output error", input_event)) @@ -378,7 +389,7 @@ def raise_warning(event): dummy_output.store = raise_warning self.pipeline._setup() self.pipeline._output["dummy"] = dummy_output - self.pipeline._input.get_next.return_value = (input_event, None) + self.pipeline._input.get_next.return_value = input_event self.pipeline.process_pipeline() mock_warning.assert_called_with( str(OutputWarning(self.pipeline._output["dummy"], "mock output warning")) @@ -407,7 +418,7 @@ def test_processor_fatal_output_error_is_logged_pipeline_is_shutdown( self, mock_log_error, mock_shut_down, _ ): self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) + self.pipeline._input.get_next.return_value = {"some": "event"} raised_error = FatalOutputError(mock.MagicMock(), "fatal output error") self.pipeline._output["dummy"].store.side_effect = raised_error self.pipeline.run() @@ -424,22 +435,30 @@ def test_processor_fatal_output_error_in_setup_is_logged(self, mock_log_error, _ mock_log_error.assert_called_with(str(raised_error)) def test_extra_data_tuple_is_passed_to_store_custom(self, _): + self.pipeline._logprep_config.pipeline = [ + {"dummy": {"type": "dummy_processor"}}, + {"dummy": {"type": "dummy_processor"}}, + ] self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) - self.pipeline._pipeline[1] = deepcopy(self.pipeline._pipeline[0]) + self.pipeline._input.get_next.return_value = {"some": "event"} self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="", data=[({"foo": "bar"}, ({"dummy": "target"},))] ) - self.pipeline._pipeline.append(deepcopy(self.pipeline._pipeline[0])) self.pipeline.process_pipeline() assert self.pipeline._input.get_next.call_count == 1 assert self.pipeline._output["dummy"].store_custom.call_count == 1 self.pipeline._output["dummy"].store_custom.assert_called_with({"foo": "bar"}, "target") def test_store_custom_calls_all_defined_outputs(self, _): - self.pipeline._output.update({"dummy1": mock.MagicMock()}) + self.pipeline._logprep_config.pipeline = [ + {"dummy": {"type": "dummy_processor"}}, + {"dummy": {"type": "dummy_processor"}}, + ] + self.pipeline._logprep_config.output = { + "dummy": {"type": "dummy_output"}, + "dummy1": {"type": "dummy_output"}, + } self.pipeline._setup() - self.pipeline._pipeline[1] = deepcopy(self.pipeline._pipeline[0]) self.pipeline._pipeline[1].process.return_value = ProcessorResult( processor_name="", data=[ @@ -449,8 +468,7 @@ def test_store_custom_calls_all_defined_outputs(self, _): ) ], ) - self.pipeline._pipeline.append(deepcopy(self.pipeline._pipeline[0])) - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) + self.pipeline._input.get_next.return_value = {"some": "event"} self.pipeline.process_pipeline() assert self.pipeline._input.get_next.call_count == 1 assert self.pipeline._output["dummy"].store_custom.call_count == 1 @@ -460,55 +478,15 @@ def test_store_custom_calls_all_defined_outputs(self, _): {"foo": "bar"}, "second_target" ) - def test_extra_data_list_is_passed_to_store_custom(self, _): + def test_setup_adds_versions_information_to_input_connector_config(self, _): self.pipeline._setup() - self.pipeline._pipeline[1] = deepcopy(self.pipeline._pipeline[0]) - self.pipeline._pipeline[1].process.return_value = ProcessorResult( - processor_name="", data=[({"foo": "bar"}, ({"dummy": "target"},))] - ) - self.pipeline._pipeline.append(deepcopy(self.pipeline._pipeline[0])) - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) - self.pipeline.process_pipeline() - assert self.pipeline._input.get_next.call_count == 1 - assert self.pipeline._output["dummy"].store_custom.call_count == 1 - self.pipeline._output["dummy"].store_custom.assert_called_with({"foo": "bar"}, "target") - - def test_setup_adds_versions_information_to_input_connector_config(self, mock_create): - self.pipeline._setup() - called_input_config = mock_create.call_args_list[1][0][0]["dummy"] + called_input_config = self.pipeline._input._called_config assert "version_information" in called_input_config, "ensure version_information is added" assert "logprep" in called_input_config.get("version_information"), "ensure logprep key" assert "configuration" in called_input_config.get("version_information"), "ensure config" assert called_input_config.get("version_information").get("logprep"), "ensure values" assert called_input_config.get("version_information").get("configuration"), "ensure values" - def test_setup_connects_output_with_input(self, _): - self.pipeline._setup() - assert self.pipeline._output["dummy"].input_connector == self.pipeline._input - - def test_setup_connects_input_with_output(self, _): - self.pipeline._setup() - assert self.pipeline._input.output_connector == self.pipeline._output["dummy"] - - def test_pipeline_does_not_call_batch_finished_callback_if_output_store_does_not_return_true( - self, _ - ): - self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) - self.pipeline._input.batch_finished_callback = mock.MagicMock() - self.pipeline._output["dummy"].store = mock.MagicMock() - self.pipeline._output["dummy"].store.return_value = None - self.pipeline.process_pipeline() - self.pipeline._input.batch_finished_callback.assert_not_called() - - def test_retrieve_and_process_data_calls_store_failed_for_non_critical_error_message(self, _): - self.pipeline._setup() - self.pipeline._input.get_next.return_value = ({"some": "event"}, "This is non critical") - self.pipeline.process_pipeline() - self.pipeline._output["dummy"].store_failed.assert_called_with( - "This is non critical", {"some": "event"}, None - ) - def test_shut_down_drains_input_queues(self, _): self.pipeline._setup() input_config = { @@ -532,13 +510,17 @@ def test_shut_down_drains_input_queues(self, _): self.pipeline._shut_down() assert self.pipeline._input.messages.qsize() == 0 - def test_pipeline_raises_http_error_from_factory_create(self, mock_create): - mock_create.side_effect = requests.HTTPError() - with raises(requests.HTTPError): - self.pipeline._setup() + def test_pipeline_raises_http_error_from_factory_create(self, _): + with mock.patch("logprep.factory.Factory.create") as mock_create: + mock_create.side_effect = requests.HTTPError() + with raises(requests.HTTPError): + self.pipeline._setup() def test_multiple_outputs(self, _): - output_config = {"kafka_output": {}, "opensearch_output": {}} + output_config = { + "kafka_output": {"type": "kafka_output"}, + "opensearch_output": {"type": "opensearch_output"}, + } self.pipeline._logprep_config.output = output_config self.pipeline._setup() assert isinstance(self.pipeline._output, dict) @@ -578,8 +560,9 @@ def test_event_with_critical_input_parsing_error_is_stored_in_error_output(self, self.pipeline._input.get_next = mock.MagicMock() self.pipeline._input.get_next.side_effect = error self.pipeline._output = {"dummy": mock.MagicMock()} + self.pipeline.enqueue_error = mock.MagicMock() self.pipeline.process_pipeline() - self.pipeline._output["dummy"].store_failed.assert_called() + self.pipeline.enqueue_error.assert_called_with(error) def test_stop_breaks_while_loop_and_shutdown_is_called(self, _): iterations = [None, None, 1] @@ -605,36 +588,175 @@ def test_shutdown_logs_fatal_errors(self, mock_error, _): logger_call = f"Couldn't gracefully shut down pipeline due to: {error}" mock_error.assert_called_with(logger_call) - def test_pipeline_result_provides_event_received(self, _): - self.pipeline._setup() - event = {"some": "event"} - self.pipeline._input.get_next.return_value = (event, None) - generic_adder = original_create( - { - "generic_adder": { - "type": "generic_adder", - "specific_rules": [ - {"filter": "some", "generic_adder": {"add": {"field": "foo"}}} - ], - "generic_rules": [], - } - } - ) - self.pipeline._pipeline = [generic_adder] - result = self.pipeline.process_pipeline() - assert result.event_received is not event, "event_received is a copy" - assert result.event_received == {"some": "event"}, "received event is as expected" - assert result.event == {"some": "event", "field": "foo"}, "processed event is as expected" - def test_process_event_can_be_bypassed_with_no_pipeline(self, _): self.pipeline._pipeline = [] - self.pipeline._input.get_next.return_value = ({"some": "event"}, None) + self.pipeline._input.get_next.return_value = {"some": "event"} with mock.patch("logprep.framework.pipeline.Pipeline.process_event") as mock_process_event: mock_process_event.return_value = None result = self.pipeline.process_pipeline() mock_process_event.assert_not_called() assert isinstance(result, type(None)) + def test_enqueue_error_logs_warning_if_no_error_queue(self, _): + error = CriticalInputError(self.pipeline._input, "test-error", "raw_input") + self.pipeline.error_queue = None + with mock.patch("logging.Logger.warning") as mock_warning: + self.pipeline.enqueue_error(error) + mock_warning.assert_called_with("No error queue defined, event was dropped") + + @pytest.mark.parametrize( + "item, expected_event", + [ + ( + CriticalOutputError(mock.MagicMock(), "this is an output error", "raw_input"), + {"event": "raw_input", "errors": "this is an output error"}, + ), + ( + CriticalOutputError(mock.MagicMock(), "this is an output error", ["raw_input"]), + {"event": "raw_input", "errors": "this is an output error"}, + ), + ( + CriticalOutputError(mock.MagicMock(), "another error", {"foo": "bar"}), + {"event": "{'foo': 'bar'}", "errors": "another error"}, + ), + ( + CriticalOutputError( + mock.MagicMock(), + "another error", + {"errors": "some error", "event": {"some": "event"}}, + ), + {"event": "{'some': 'event'}", "errors": "some error"}, + ), + ( + CriticalOutputError( + mock.MagicMock(), "another error", [{"foo": "bar"}, {"foo": "baz"}] + ), + {"event": "{'foo': 'bar'}", "errors": "another error"}, + ), + ( + CriticalOutputError( + mock.MagicMock(), + "just another error", + [{"event": {"test": "message"}, "errors": {"error": "error_msg"}}], + ), + {"event": "{'test': 'message'}", "errors": "{'error': 'error_msg'}"}, + ), + ( + CriticalOutputError( + mock.MagicMock(), + "another error message", + [ + {"event": {"test": f"message{i}"}, "errors": {"error": "error_msg"}} + for i in range(2) + ], + ), + {"event": "{'test': 'message0'}", "errors": "{'error': 'error_msg'}"}, + ), + ( + CriticalInputError(mock.MagicMock(), "this is an input error", "raw_input"), + {"event": "raw_input", "errors": "this is an input error"}, + ), + ( + CriticalInputParsingError( + mock.MagicMock(), "this is an input parsing error", "raw_input" + ), + {"event": "raw_input", "errors": "this is an input parsing error"}, + ), + ( + PipelineResult( + event={"test": "message"}, + pipeline=[ + get_mock_create()( + {"mock_processor1": {"type": "mock_processor_with_errors"}} + ) + ], + ), + { + "event": "{'test': 'message'}", + "errors": "'this is a processing critical error' -> rule.id: 'test_rule_id'", + }, + ), + ( + PipelineResult( + event={"test": "message"}, + pipeline=[ + get_mock_create()( + {"mock_processor1": {"type": "mock_processor_with_errors"}} + ), + get_mock_create()( + {"mock_processor1": {"type": "mock_processor_with_errors"}} + ), + ], + ), + { + "event": "{'test': 'message'}", + "errors": "'this is a processing critical error' -> rule.id: 'test_rule_id', 'this is a processing critical error' -> rule.id: 'test_rule_id'", + }, + ), + ( + "some string", + {"event": "some string", "errors": "Unknown error"}, + ), + ( + {"some": "dict"}, + {"event": "{'some': 'dict'}", "errors": "Unknown error"}, + ), + ( + ["some", "list"], + {"event": "some", "errors": "Unknown error"}, + ), + ], + ) + def test_enqueue_error_handles_items(self, _, item, expected_event): + self.pipeline.enqueue_error(item) + enqueued_item = self.pipeline.error_queue.get(0.01) + assert enqueued_item == expected_event + + def test_enqueue_error_calls_batch_finished_callback(self, _): + error = CriticalInputError(self.pipeline._input, "test-error", "raw_input") + self.pipeline._input.batch_finished_callback = mock.MagicMock() + self.pipeline.error_queue = queue.Queue() + self.pipeline.enqueue_error(error) + self.pipeline._input.batch_finished_callback.assert_called() + + def test_enqueue_error_calls_batch_finished_callback_without_error_queue(self, _): + error = CriticalInputError(self.pipeline._input, "test-error", "raw_input") + self.pipeline._input.batch_finished_callback = mock.MagicMock() + self.pipeline.error_queue = None + self.pipeline.enqueue_error(error) + self.pipeline._input.batch_finished_callback.assert_called() + + def test_enqueue_error_logs_input_on_exception(self, _): + error = CriticalInputError(self.pipeline._input, "test-error", "raw_input") + self.pipeline.error_queue = queue.Queue() + self.pipeline.error_queue.put = mock.MagicMock(side_effect=Exception) + with mock.patch("logging.Logger.error") as mock_error: + self.pipeline.enqueue_error(error) + mock_error.assert_called() + + def test_enqueue_error_counts_failed_event_for_critical_output_with_single_event(self, _): + self.pipeline._setup() + self.pipeline.metrics.number_of_failed_events = 0 + error = CriticalOutputError(self.pipeline._output["dummy"], "error", {"some": "event"}) + self.pipeline.enqueue_error(error) + assert self.pipeline.metrics.number_of_failed_events == 1 + + def test_enqueue_error_counts_failed_event_for_multi_event_output_error(self, _): + self.pipeline._setup() + self.pipeline.metrics.number_of_failed_events = 0 + error = CriticalOutputError( + self.pipeline._output["dummy"], "error", [{"some": "event"}, {"some": "other"}] + ) + self.pipeline.enqueue_error(error) + assert self.pipeline.metrics.number_of_failed_events == 2 + + def test_enqueue_error_counts_failed_event_for_pipeline_result(self, mock_create): + self.pipeline.metrics.number_of_failed_events = 0 + mock_result = mock.create_autospec(spec=PipelineResult) + mock_result.pipeline = self.pipeline._pipeline + self.pipeline.enqueue_error(mock_result) + assert self.pipeline.metrics.number_of_failed_events == 1 + class TestPipelineWithActualInput: def setup_method(self): @@ -682,15 +804,21 @@ def test_pipeline_without_output_connector_and_two_input_events_and_preprocessor assert "pseudonym" in result.event.get("winlog", {}).get("event_data", {}).get("IpAddress") assert "arrival_time" in result.event - def test_pipeline_hmac_error_message_without_output_connector(self): + def test_pipeline_hmac_error_was_send_to_error_queue(self): self.config.input["test_input"]["documents"] = [{"applyrule": "yes"}] self.config.input["test_input"]["preprocessing"] = { "hmac": {"target": "non_existing_field", "key": "secret", "output_field": "hmac"} } pipeline = Pipeline(config=self.config) + pipeline.enqueue_error = mock.MagicMock() assert pipeline._output is None - result = pipeline.process_pipeline() - assert result.event["hmac"]["hmac"] == "error" + _ = pipeline.process_pipeline() + expected_error = CriticalInputError( + pipeline._input, + "Couldn't find the hmac target field 'non_existing_field'", + b'{"applyrule":"yes"}', + ) + pipeline.enqueue_error.assert_called_with(expected_error) def test_pipeline_run_raises_assertion_when_run_without_input(self): self.config.input = {} @@ -743,3 +871,132 @@ def test_health_returns_health_functions_with_multiple_outputs(self): assert isinstance(health, Tuple) assert len(health) > 0 assert all(callable(health_function) for health_function in health) + + +class TestPipelineResult: + + @pytest.mark.parametrize( + "parameters, error, message", + [ + ( + { + "event": {"some": "event"}, + "pipeline": [], + }, + ValueError, + "Length of 'pipeline' must be >= 1", + ), + ( + { + "event": {"some": "event"}, + "pipeline": [], + "results": [], + }, + TypeError, + "got an unexpected keyword argument 'results'", + ), + ( + { + "event": {"some": "event"}, + "pipeline": [ + Factory.create( + { + "dummy": { + "type": "dropper", + "specific_rules": [], + "generic_rules": [], + } + } + ) + ], + "results": [], + }, + TypeError, + "got an unexpected keyword argument 'results'", + ), + ( + { + "event": {"some": "event"}, + "pipeline": [ + Factory.create( + { + "dummy": { + "type": "dropper", + "specific_rules": [], + "generic_rules": [], + } + } + ) + ], + }, + None, + None, + ), + ( + { + "event": {"some": "event"}, + "pipeline": [ + mock.MagicMock(), + ], + }, + TypeError, + "'pipeline' must be first_sleep_time + + +class TestOutputQueueListener: + + @pytest.mark.parametrize( + "parameters, error", + [ + ( + { + "config": {"random_name": {"type": "dummy_output"}}, + "queue": ThrottlingQueue(multiprocessing.get_context(), 100), + "target": "random", + }, + None, + ), + ( + { + "config": {"random_name": {"type": "dummy_output"}}, + "queue": ThrottlingQueue(multiprocessing.get_context(), 100), + "target": lambda x: x, + }, + TypeError, + ), + ( + { + "config": {"random_name": {"type": "dummy_output"}}, + "queue": "I am not a queue", + "target": "random", + }, + TypeError, + ), + ( + { + "config": "I am not a config", + "queue": ThrottlingQueue(multiprocessing.get_context(), 100), + "target": "random", + }, + TypeError, + ), + ], + ) + def test_sets_parameters(self, parameters, error): + if error: + with pytest.raises(error): + OutputQueueListener(**parameters) + else: + OutputQueueListener(**parameters) + + def test_init_sets_process_but_does_not_start_it(self): + target = "store" + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + output_config = {"random_name": {"type": "dummy_output"}} + listener = OutputQueueListener(queue, target, output_config) + assert listener._process is not None + assert isinstance(listener._process, multiprocessing.Process) + assert not listener._process.is_alive() + + def test_init_sets_process_target(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + with mock.patch("multiprocessing.Process") as mock_process: + listener = OutputQueueListener(queue, target, output_config) + mock_process.assert_called_with(target=listener._listen, daemon=True) + + def test_start_starts_process(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch.object(listener._process, "start") as mock_start: + listener.start() + mock_start.assert_called() + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + new=mock.MagicMock(), + ) + def test_sentinel_breaks_while_loop(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put(listener.sentinel) + with mock.patch("logging.Logger.debug") as mock_debug: + listener._listen() + mock_debug.assert_called_with("Got sentinel. Stopping listener.") + + def test_stop_injects_sentinel(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + with mock.patch("multiprocessing.Process"): + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch.object(queue, "put") as mock_put: + listener.stop() + mock_put.assert_called_with(listener.sentinel) + + def test_stop_joins_process(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + with mock.patch("multiprocessing.Process"): + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + listener.stop() + listener._process.join.assert_called() + + def test_listen_calls_target(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + queue.empty = mock.MagicMock(return_value=True) + with mock.patch("logprep.connector.dummy.output.DummyOutput.store") as mock_store: + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put("test") + listener.queue.put(listener.sentinel) + listener._listen() + mock_store.assert_called_with("test") + + def test_listen_creates_component(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + queue.empty = mock.MagicMock(return_value=True) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch("logprep.factory.Factory.create") as mock_create: + listener.queue.put("test") + listener.queue.put(listener.sentinel) + listener._listen() + mock_create.assert_called_with(output_config) + + def test_listen_setups_component(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + queue.empty = mock.MagicMock(return_value=True) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch("logprep.connector.dummy.output.DummyOutput.setup") as mock_setup: + listener.queue.put("test") + listener.queue.put(listener.sentinel) + listener._listen() + mock_setup.assert_called() + + def test_get_component_instance_raises_if_setup_not_successful(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch("logprep.connector.dummy.output.DummyOutput.setup") as mock_setup: + mock_setup.side_effect = SystemExit(4) + with pytest.raises(SystemExit, match="4"): + listener._listen() + + def test_listen_calls_component_shutdown_by_injecting_sentinel(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + queue.empty = mock.MagicMock(return_value=True) + listener = OutputQueueListener(queue, target, output_config) + with mock.patch("logprep.connector.dummy.output.DummyOutput.shut_down") as mock_shutdown: + listener.queue.put("test") + listener.queue.put(listener.sentinel) + listener._listen() + mock_shutdown.assert_called() + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + new=mock.MagicMock(), + ) + def test_listen_drains_queue_on_shutdown(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = multiprocessing.Queue() + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put(listener.sentinel) + listener.queue.put("test") + listener._listen() + assert listener.queue.qsize() == 0 + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + new=mock.MagicMock(), + ) + def test_listen_ensures_error_queue_is_closed_after_drained(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put(listener.sentinel) + listener._listen() + with pytest.raises(ValueError, match="is closed"): + listener.queue.put("test") + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + ) + def test_listen_ignores_sync_item_1_and_sentinel(self, mock_get_output_instance): + mock_component = mock.MagicMock() + mock_target = mock.MagicMock() + mock_component.store = mock_target + mock_get_output_instance.return_value = mock_component + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put(1) + listener.queue.put(listener.sentinel) + listener._listen() + mock_target.assert_not_called() + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + ) + @mock.patch("logging.Logger.error") + def test_listen_logs_event_on_unexpected_exception(self, mock_error, mock_get_output_instance): + mock_component = mock.MagicMock() + mock_target = mock.MagicMock() + mock_target.side_effect = Exception("TestException") + mock_component.store = mock_target + mock_get_output_instance.return_value = mock_component + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + event = {"event": "test"} + listener.queue.put(event) + listener.queue.put(listener.sentinel) + time.sleep(0.1) # test will sometimes fail without it, probably due to ThrottlingQueue + listener._listen() + expected_error_log = ( + f"[Error Event] Couldn't enqueue error item due to: TestException | Item: '{event}'" + ) + mock_error.assert_called_with(expected_error_log) + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + new=mock.MagicMock(), + ) + def test_drain_queue_ignores_sync_item_1_and_sentinel(self): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + listener.queue.put(1) + listener.queue.put(listener.sentinel) + mock_target = mock.MagicMock() + listener._drain_queue(mock_target) + mock_target.assert_not_called() + + @mock.patch( + "logprep.framework.pipeline_manager.OutputQueueListener.get_output_instance", + new=mock.MagicMock(), + ) + @mock.patch("logging.Logger.error") + def test_drain_queue_logs_event_on_unexpected_exception(self, mock_error): + target = "store" + output_config = {"random_name": {"type": "dummy_output"}} + queue = ThrottlingQueue(multiprocessing.get_context(), 100) + listener = OutputQueueListener(queue, target, output_config) + event = {"event": "test"} + listener.queue.put(event) + mock_target = mock.MagicMock() + mock_target.side_effect = Exception("TestException") + time.sleep(0.1) # test will sometimes fail without it, probably due to ThrottlingQueue + listener._drain_queue(mock_target) + expected_error_log = ( + f"[Error Event] Couldn't enqueue error item due to: TestException | Item: '{event}'" + ) + mock_error.assert_called_with(expected_error_log) diff --git a/tests/unit/processor/base.py b/tests/unit/processor/base.py index 9f1c4225b..a67ac640e 100644 --- a/tests/unit/processor/base.py +++ b/tests/unit/processor/base.py @@ -322,9 +322,7 @@ def test_process_collects_errors_in_result_object(self): with mock.patch.object( self.object, "_apply_rules", - side_effect=ProcessingCriticalError( - "side effect", rule=self.object.rules[0], event=self.match_all_event - ), + side_effect=ProcessingCriticalError("side effect", rule=self.object.rules[0]), ): result = self.object.process(self.match_all_event) assert len(result.errors) > 0, "minimum one error should be in result object" diff --git a/tests/unit/test_run_logprep.py b/tests/unit/test_run_logprep.py index b5b419a0e..be61938be 100644 --- a/tests/unit/test_run_logprep.py +++ b/tests/unit/test_run_logprep.py @@ -124,7 +124,7 @@ def test_test_config_verifies_configuration_successfully(self, mock_verify): @mock.patch("logprep.util.configuration.Configuration._verify") def test_test_config_verifies_configuration_unsuccessfully(self, mock_verify): - mock_verify.side_effect = InvalidConfigurationError + mock_verify.side_effect = InvalidConfigurationError("test error") args = ["test", "config", "tests/testdata/config/config.yml"] result = self.cli_runner.invoke(cli, args) assert result.exit_code == EXITCODES.CONFIGURATION_ERROR.value @@ -224,7 +224,7 @@ def test_main_calls_runner_stop_on_any_exception(self, mock_runner): def test_logprep_exits_on_invalid_configuration(self): with mock.patch("logprep.util.configuration.Configuration._verify") as mock_verify: - mock_verify.side_effect = InvalidConfigurationError + mock_verify.side_effect = InvalidConfigurationError("test error") config_path = "tests/testdata/config/config.yml" result = self.cli_runner.invoke(cli, ["run", config_path]) assert result.exit_code == EXITCODES.CONFIGURATION_ERROR.value diff --git a/tests/unit/test_runner.py b/tests/unit/test_runner.py index 3ff790807..7c533bd49 100644 --- a/tests/unit/test_runner.py +++ b/tests/unit/test_runner.py @@ -5,7 +5,6 @@ # pylint: disable=attribute-defined-outside-init import re import uuid -from functools import partial from importlib.metadata import version from pathlib import Path from unittest import mock @@ -132,6 +131,18 @@ def test_iteration_calls_run_pending(self, mock_run_pending, runner): runner.start() mock_run_pending.call_count = 3 + def test_iteration_sets_error_queue_size(self, runner): + with mock.patch.object(runner, "_manager") as mock_manager: + mock_manager.restart_count = 0 + runner.metrics.number_of_events_in_error_queue = 0 + mock_manager.should_exit.side_effect = [False, False, True] + mock_manager.error_queue.qsize.return_value = 42 + with pytest.raises(SystemExit): + runner.start() + assert ( + runner.metrics.number_of_events_in_error_queue == 84 + ) # because of mocking with int + def test_iteration_calls_should_exit(self, runner): with mock.patch.object(runner, "_manager") as mock_manager: mock_manager.restart_count = 0 diff --git a/tests/unit/util/test_configuration.py b/tests/unit/util/test_configuration.py index 19a02147f..35cb2dca1 100644 --- a/tests/unit/util/test_configuration.py +++ b/tests/unit/util/test_configuration.py @@ -499,6 +499,13 @@ def test_verify_passes_for_valid_configuration(self): }, 1, ), + ( + "error_output with unknown type", + { + "error_output": {"kafka_output": {"type": "UNKNOWN"}}, + }, + 1, + ), ], ) def test_verify_verifies_config(self, tmp_path, test_case, test_config, error_count): @@ -538,7 +545,6 @@ def test_verify_verifies_config(self, tmp_path, test_case, test_config, error_co kafka: type: confluentkafka_output topic: producer - error_topic: producer_error flush_timeout: 30 send_timeout: 2 kafka_config: