diff --git a/CHANGELOG.md b/CHANGELOG.md index ea9ac873..2e2bab9a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,8 @@ All notable changes to this project will be documented in this file. - Support floating tags for product images via the new `spec.image.stackableVersionPolicy` field ([#876]). - Add `/ready` endpoint to the operator Deployment, which reports the CRD installation status ([#880]). +- The logs of the `containerdebug` process are now collected by the Vector agent and forwarded to + the Vector aggregator ([#894]). ### Changed @@ -48,6 +50,10 @@ All notable changes to this project will be documented in this file. See [our internal issue](https://github.com/stackabletech/hdfs-operator/issues/626) and [the fix](https://github.com/kube-rs/kube/pull/2042) for details ([#860]). - The operator now watches all resources that it creates and early-exits the reconcile action when the cluster is marked for deletion ([#867]). +- The `containerdebug` process writes its log file again. The operator set + `CONTAINERDEBUG_LOG_DIRECTORY`, which containerdebug stopped reading in its version 0.2.0 when it + moved to `stackable-telemetry`; the directory is now set via `FILE_LOG_DIRECTORY`. The file is + rotated hourly and at most two files are kept, because rotation is opt-in ([#894]). ### Remove @@ -71,6 +77,7 @@ All notable changes to this project will be documented in this file. [#889]: https://github.com/stackabletech/druid-operator/pull/889 [#891]: https://github.com/stackabletech/druid-operator/pull/891 [#892]: https://github.com/stackabletech/druid-operator/pull/892 +[#894]: https://github.com/stackabletech/druid-operator/pull/894 ## [26.7.0] - 2026-07-21 diff --git a/docs/modules/druid/pages/usage-guide/logging.adoc b/docs/modules/druid/pages/usage-guide/logging.adoc index 83388b81..c07c2fc7 100644 --- a/docs/modules/druid/pages/usage-guide/logging.adoc +++ b/docs/modules/druid/pages/usage-guide/logging.adoc @@ -30,4 +30,12 @@ spec: enableVectorAgent: true ---- +NOTE: The logs of the xref:concepts:observability/containerdebug.adoc[`containerdebug` process] are collected as well. +They are labelled `container: containerdebug`, although no such Kubernetes container exists. +The process runs in the background of the `druid` container. +The label comes from `/stackable/log/containerdebug`, the directory which the operator sets with the `FILE_LOG_DIRECTORY` environment variable and from which the Vector agent derives the container name. +Overriding `FILE_LOG_DIRECTORY` with `envOverrides` therefore changes how these logs are aggregated. +The agent only collects files one level below `/stackable/log`, so a sibling directory such as `/stackable/log/druid` relabels the events instead of dropping them, while any deeper or shallower path stops the aggregation. +A path outside `/stackable/log` also leaves the size-capped log volume. + Further information on how to configure logging, can be found in xref:concepts:logging.adoc[]. diff --git a/rust/operator-binary/src/controller/build/container.rs b/rust/operator-binary/src/controller/build/container.rs index ef3358e1..d07ee0e5 100644 --- a/rust/operator-binary/src/controller/build/container.rs +++ b/rust/operator-binary/src/controller/build/container.rs @@ -7,6 +7,7 @@ use std::str::FromStr; +use const_format::concatcp; use snafu::{ResultExt, Snafu}; use stackable_operator::{ builder::pod::{ @@ -17,7 +18,7 @@ use stackable_operator::{ }, product_logging, v2::{ - builder::pod::container::{EnvVarName, EnvVarSet, new_container_builder}, + builder::pod::container::{EnvVarSet, new_container_builder}, product_logging::framework::{ STACKABLE_LOG_DIR, ValidatedContainerLogConfigChoice, vector_container, }, @@ -39,8 +40,9 @@ use crate::{ }, }, crd::{ - Container, DRUID_CONFIG_DIRECTORY, DeepStorageSpec, HDFS_CONFIG_DIRECTORY, - LOG_CONFIG_DIRECTORY, METRICS_PORT, METRICS_PORT_NAME, RW_CONFIG_DIRECTORY, + Container, DRUID_CONFIG_DIRECTORY, DeepStorageSpec, FILE_LOG_DIRECTORY, FILE_LOG_MAX_FILES, + FILE_LOG_ROTATION_PERIOD, HDFS_CONFIG_DIRECTORY, LOG_CONFIG_DIRECTORY, METRICS_PORT, + METRICS_PORT_NAME, RW_CONFIG_DIRECTORY, }, }; @@ -51,9 +53,6 @@ stackable_operator::constant!(pub(crate) LOG_CONFIG_VOLUME_NAME: VolumeName = "l stackable_operator::constant!(pub(crate) LOG_VOLUME_NAME: VolumeName = "log"); stackable_operator::constant!(pub(crate) RW_CONFIG_VOLUME_NAME: VolumeName = "rwconfig"); -// Needed for the `containerdebug` process to log its tracing information to. -stackable_operator::constant!(pub(crate) CONTAINERDEBUG_LOG_DIRECTORY: EnvVarName = "CONTAINERDEBUG_LOG_DIRECTORY"); - // volume mount directory (not a volume name) const USERDATA_MOUNTPOINT: &str = "/stackable/userdata"; @@ -269,10 +268,20 @@ pub(crate) fn containers_and_volumes(inputs: &RoleGroupInputs) -> Result = env .iter() - .filter(|env_var| env_var.name == CONTAINERDEBUG_LOG_DIRECTORY.as_ref()) + .filter(|env_var| env_var.name == FILE_LOG_DIRECTORY.as_ref()) .collect(); assert_eq!( containerdebug.len(), diff --git a/rust/operator-binary/src/crd/mod.rs b/rust/operator-binary/src/crd/mod.rs index 0a6697f9..1e49e15c 100644 --- a/rust/operator-binary/src/crd/mod.rs +++ b/rust/operator-binary/src/crd/mod.rs @@ -91,6 +91,14 @@ pub const METRICS_PORT: Port = Port(9090); constant!(pub COOKIE_PASSPHRASE_ENV: EnvVarName = "OIDC_COOKIE_PASSPHRASE"); constant!(pub COOKIE_PASSPHRASE_SECRET_KEY: SecretKey = "OIDC_COOKIE_PASSPHRASE"); +// The `stackable-telemetry` variables which configure the file logs of the `containerdebug` +// process. They are set on the Druid container in `container`, and the start command below +// references the directory as a shell variable, so that an `envOverrides` entry for it takes +// effect in both places. +constant!(pub FILE_LOG_DIRECTORY: EnvVarName = "FILE_LOG_DIRECTORY"); +constant!(pub FILE_LOG_MAX_FILES: EnvVarName = "FILE_LOG_MAX_FILES"); +constant!(pub FILE_LOG_ROTATION_PERIOD: EnvVarName = "FILE_LOG_ROTATION_PERIOD"); + /// Formats a Druid [dynamic config](https://druid.apache.org/docs/latest/operations/dynamic-config-provider) /// reference to an environment variable, i.e. `${env:NAME}`. pub(crate) fn env_var_reference(name: impl std::fmt::Display) -> String { @@ -485,6 +493,7 @@ impl DruidRole { {COMMON_BASH_TRAP_FUNCTIONS} {remove_vector_shutdown_file_command} prepare_signal_handlers + mkdir --parents \"${file_log_directory}\" || true containerdebug --output={STACKABLE_LOG_DIR}/containerdebug-state.json --loop & /stackable/druid/bin/run-druid {process_name} {RW_CONFIG_DIRECTORY} & echo \"$!\" >> /tmp/DRUID_PID @@ -492,6 +501,7 @@ impl DruidRole { {create_vector_shutdown_file_command} ", process_name = self.get_process_name(), + file_log_directory = FILE_LOG_DIRECTORY.as_ref(), remove_vector_shutdown_file_command = remove_vector_shutdown_file_command(STACKABLE_LOG_DIR), create_vector_shutdown_file_command = @@ -684,6 +694,9 @@ mod tests { let _ = *HISTORICAL_ROLE_NAME; let _ = *MIDDLE_MANAGER_ROLE_NAME; let _ = *ROUTER_ROLE_NAME; + let _ = *FILE_LOG_DIRECTORY; + let _ = *FILE_LOG_MAX_FILES; + let _ = *FILE_LOG_ROTATION_PERIOD; let _ = *COOKIE_PASSPHRASE_ENV; let _ = *COOKIE_PASSPHRASE_SECRET_KEY; let _ = *DRUID_DEFAULT_LISTENER_CLASS; diff --git a/tests/templates/kuttl/logging/01_druid-vector-aggregator-values.yaml.j2 b/tests/templates/kuttl/logging/01_druid-vector-aggregator-values.yaml.j2 index b8cc3c1a..c613ff19 100644 --- a/tests/templates/kuttl/logging/01_druid-vector-aggregator-values.yaml.j2 +++ b/tests/templates/kuttl/logging/01_druid-vector-aggregator-values.yaml.j2 @@ -22,191 +22,293 @@ customConfig: transforms: validEvents: type: filter - inputs: [vector] + inputs: + - vector condition: is_null(.errors) filteredAutomaticLogConfigBrokerDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-automatic-log-config-0" && .container == "druid" filteredAutomaticLogConfigBrokerPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-automatic-log-config-0" && .container == "prepare" + filteredAutomaticLogConfigBrokerContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-broker-automatic-log-config-0" && + .container == "containerdebug" filteredAutomaticLogConfigBrokerVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-automatic-log-config-0" && .container == "vector" filteredCustomLogConfigBrokerDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-custom-log-config-0" && .container == "druid" filteredCustomLogConfigBrokerPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-custom-log-config-0" && .container == "prepare" + filteredCustomLogConfigBrokerContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-broker-custom-log-config-0" && + .container == "containerdebug" filteredCustomLogConfigBrokerVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-broker-custom-log-config-0" && .container == "vector" filteredAutomaticLogConfigCoordinatorDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-automatic-log-config-0" && .container == "druid" filteredAutomaticLogConfigCoordinatorPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-automatic-log-config-0" && .container == "prepare" + filteredAutomaticLogConfigCoordinatorContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-coordinator-automatic-log-config-0" && + .container == "containerdebug" filteredAutomaticLogConfigCoordinatorVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-automatic-log-config-0" && .container == "vector" filteredCustomLogConfigCoordinatorDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-custom-log-config-0" && .container == "druid" filteredCustomLogConfigCoordinatorPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-custom-log-config-0" && .container == "prepare" + filteredCustomLogConfigCoordinatorContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-coordinator-custom-log-config-0" && + .container == "containerdebug" filteredCustomLogConfigCoordinatorVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-coordinator-custom-log-config-0" && .container == "vector" filteredAutomaticLogConfigHistoricalDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-automatic-log-config-0" && .container == "druid" filteredAutomaticLogConfigHistoricalPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-automatic-log-config-0" && .container == "prepare" + filteredAutomaticLogConfigHistoricalContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-historical-automatic-log-config-0" && + .container == "containerdebug" filteredAutomaticLogConfigHistoricalVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-automatic-log-config-0" && .container == "vector" filteredCustomLogConfigHistoricalDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-custom-log-config-0" && .container == "druid" filteredCustomLogConfigHistoricalPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-custom-log-config-0" && .container == "prepare" + filteredCustomLogConfigHistoricalContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-historical-custom-log-config-0" && + .container == "containerdebug" filteredCustomLogConfigHistoricalVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-historical-custom-log-config-0" && .container == "vector" filteredAutomaticLogConfigMiddlemanagerDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-automatic-log-config-0" && .container == "druid" filteredAutomaticLogConfigMiddlemanagerPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-automatic-log-config-0" && .container == "prepare" + filteredAutomaticLogConfigMiddlemanagerContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-middlemanager-automatic-log-config-0" && + .container == "containerdebug" filteredAutomaticLogConfigMiddlemanagerVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-automatic-log-config-0" && .container == "vector" filteredCustomLogConfigMiddlemanagerDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-custom-log-config-0" && .container == "druid" filteredCustomLogConfigMiddlemanagerPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-custom-log-config-0" && .container == "prepare" + filteredCustomLogConfigMiddlemanagerContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-middlemanager-custom-log-config-0" && + .container == "containerdebug" filteredCustomLogConfigMiddlemanagerVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-middlemanager-custom-log-config-0" && .container == "vector" filteredAutomaticLogConfigRouterDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-automatic-log-config-0" && .container == "druid" filteredAutomaticLogConfigRouterPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-automatic-log-config-0" && .container == "prepare" + filteredAutomaticLogConfigRouterContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-router-automatic-log-config-0" && + .container == "containerdebug" filteredAutomaticLogConfigRouterVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-automatic-log-config-0" && .container == "vector" filteredCustomLogConfigRouterDruid: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-custom-log-config-0" && .container == "druid" filteredCustomLogConfigRouterPrepare: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-custom-log-config-0" && .container == "prepare" + filteredCustomLogConfigRouterContainerdebug: + type: filter + inputs: + - validEvents + condition: >- + .pod == "test-druid-router-custom-log-config-0" && + .container == "containerdebug" filteredCustomLogConfigRouterVector: type: filter - inputs: [validEvents] + inputs: + - validEvents condition: >- .pod == "test-druid-router-custom-log-config-0" && .container == "vector" filteredInvalidEvents: type: filter - inputs: [vector] + inputs: + - vector condition: |- .timestamp == from_unix_timestamp!(0) || is_null(.level) || @@ -214,11 +316,29 @@ customConfig: is_null(.message) sinks: test: - inputs: [filtered*] + inputs: + - filtered* type: blackhole + # Shows all events received from the agents. This sink is intentional and + # not a debugging leftover: if a "filtered*" transform gathers no event, + # then the assertion only reports a count, whereas this log shows which + # pod and container names actually arrived. A failure in CI cannot be + # reproduced by enabling this afterwards, so it is kept enabled at the + # price of the log volume. + stdout: + inputs: + - vector + type: console + encoding: + codec: json + buffer: + # Avoid back pressure from a stalling stdout. The test should not + # fail because of a sink which only aids debugging. + when_full: drop_newest {% if lookup('env', 'VECTOR_AGGREGATOR') %} aggregator: - inputs: [vector] + inputs: + - vector type: vector routing: endpoints: diff --git a/tests/templates/kuttl/smoke/53-assert.yaml.j2 b/tests/templates/kuttl/smoke/53-assert.yaml.j2 index 5ec8ee2d..d9979111 100644 --- a/tests/templates/kuttl/smoke/53-assert.yaml.j2 +++ b/tests/templates/kuttl/smoke/53-assert.yaml.j2 @@ -27,6 +27,12 @@ sources: - ${LOG_DIR}/*/*.log4j2.xml line_delimiter: "\r\n" + # Reads the logs of the containerdebug process + files_tracing_rs: + type: file + include: + - ${LOG_DIR}/*/*.tracing-rs.json + transforms: processed_files_stdout: inputs: @@ -175,12 +181,93 @@ transforms: } } + # Transforms the tracing-rs JSON logs written by the containerdebug process + processed_files_tracing_rs: + inputs: + - files_tracing_rs + type: remap + source: | + raw_message = string!(.message) + + .timestamp = now() + .logger = "" + .level = "INFO" + .message = "" + .errors = [] + + parsed_event, err = parse_json(raw_message) + if err != null { + error = "JSON not parsable: " + err + .errors = push(.errors, error) + log(error, level: "warn") + .message = raw_message + } else if !is_object(parsed_event) { + error = "Parsed event is not a JSON object." + .errors = push(.errors, error) + log(error, level: "warn") + .message = raw_message + } else { + event = object!(parsed_event) + + timestamp_string, err = string(event.timestamp) + if err == null { + parsed_timestamp, err = parse_timestamp(timestamp_string, "%+") + if err == null { + .timestamp = parsed_timestamp + } else { + .errors = push(.errors, "Timestamp not parsable, using current time instead: " + err) + } + } else { + .errors = push(.errors, "Timestamp not found, using current time instead.") + } + + .logger, err = string(event.target) + if err != null || is_empty(.logger) { + .errors = push(.errors, "Logger/target not found.") + } + + level, err = string(event.level) + if err != null { + .errors = push(.errors, "Level not found, using \"" + .level + "\" instead.") + } else if !includes(["TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"], upcase(level)) { + .errors = push(.errors, "Level \"" + level + "\" unknown, using \"" + .level + "\" instead.") + } else { + .level = upcase(level) + } + + fields, err = object(event.fields) + if err == null { + message, err = string(fields.message) + if err == null { + # The message is prepended to the other fields, so remove it from + # them. + del(fields.message) + } else { + # Keep an unusable message among the other fields instead of + # discarding its content. + message = "" + } + + other_fields = encode_key_value(fields, field_delimiter: "\n") + .message = join!(compact([message, other_fields]), "\n\n") + } else { + .errors = push(.errors, "Fields are not an object.") + # Fall back to the raw line, so that its content is not lost. + .message = raw_message + } + + if is_empty(.message) { + .errors = push(.errors, "Message not found.") + } + } + # Extends the processed files with the fields "container" and "file" extended_logs_files: inputs: - processed_files_stdout - processed_files_stderr - processed_files_log4j2 + - processed_files_tracing_rs type: remap source: | del(.source_type)