Observability

Hemdall implements different observability to support easier operation and integration in different APM products. The following sections provide insights about what can be expected.

Logging in Heimdall

Heimdall’s implementation uses zerolog - Zero Allocation JSON Logger, which can however also log in plain text. All emitted log statements include information related to distributed tracing (if tracing is enabled) so that not only log statements can be correlated to traces, but also all log statements belonging to single request/transaction can be correlated as well.

Available Logging configuration options are described in Logging Configuration.

Regular Log Events

If you configure Heimdall to log in text format, you can expect output similar to the one shown below:

2022-08-03T12:51:48+02:00 INF Opentelemetry tracing initialized.
2022-08-03T12:51:48+02:00 INF Instantiating in memory cache
2022-08-03T12:51:48+02:00 DBG Creating rule set event queue.
2022-08-03T12:51:48+02:00 INF Loading pipeline definitions
2022-08-03T12:51:48+02:00 DBG Loading definitions for authenticators
2022-08-03T12:51:48+02:00 DBG Loading pipeline definition id=noop_authenticator type=noop
2022-08-03T12:51:48+02:00 DBG Loading pipeline definition id=anonymous_authenticator type=anonymous
...
2022-08-03T12:51:52+02:00 DBG Decision endpoint called
2022-08-03T12:51:52+02:00 DBG Executing default rule
2022-08-03T12:51:52+02:00 DBG Authenticating using anonymous authenticator
2022-08-03T12:51:52+02:00 DBG Mutating using JWT mutator
2022-08-03T12:51:52+02:00 DBG Generating new JWT
2022-08-03T12:51:52+02:00 DBG Finalizing request

Usage of this format is not recommended for production deployments as it requires more computational resources and is hence slow.

Otherwise, if you configure it to use gelf (see GELF for format details) format, the output will look as follows:

{"_level_name": "INFO", "version":"1.1", "host": "unknown", "timestamp": 1659523288,
 "level": 6, "short_message": "Opentracing tracer initialized."}
{"_level_name": "INFO", "version": "1.1", "host": "unknown", "timestamp": 1659523288,
 "level": 6, "short_message": "Instantiating in memory cache"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523288,
 "level": 7, "short_message": "Creating rule set event queue."}
{"_level_name": "INFO", "version": "1.1", "host": "unknown", "timestamp": 1659523288,
 "level": 6, "short_message": "Loading pipeline definitions"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523288,
 "level": 7,"short_message": "Loading definitions for authenticators"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "id": "noop_authenticator",
 "type": "noop","timestamp": 1659523288,
 "level": 7, "short_message": "Loading pipeline definition"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "id": "anonymous_authenticator",
 "type": "anonymous","timestamp": 1659523288,
 "level": 7, "short_message": "Loading pipeline definition"}

...

{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Decision endpoint called"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp":1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Executing default rule"}
{"_level_name": "DEBUG", "version":"1.1", "host": "unknown", "timestamp":1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Authenticating using anonymous authenticator"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Mutating using JWT mutator"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Generating new JWT"}
{"_level_name": "DEBUG", "version": "1.1", "host": "unknown", "timestamp": 1659523295,
 "level": 7, "_parent_id": "3449bda63ed70206", "_span_id": "f57c007257fee0ed",
 "_trace_id": "00000000000000000a5af97bffe6a8a2", "short_message": "Finalizing request"}

Each log statement does also include the following fields in both log formats for incoming requests if tracing is enabled:

_trace_id - The trace id as defined by OpenTelemetry.
_span_id - The span id as defined by OpenTelemetry of the current transaction.
_parent_id - The span id of the callee, which started the given transaction. Only present if the callee set the corresponding tracing header.

Access Log Events

In addition to regular logs, Heimdall emits access logs. These events are always emitted regardless the configured log level and the log level of these events in the log output is always INFO.

Each request to any of Heimdall’s endpoints will result in two access events:

event describing the start of the transaction, and an
event describing the finalization of the transaction.

Following are the fields, which are always set for both events:

_tx_start - Timestamp in Unix epoch format, when the transaction started.
_client_ip - The IP of the client of the request.
_http_method - The HTTP method used by the client while calling heimdall’s endpoint.
_http_path - The used HTTP path.
_http_user_agent - The agent used by the client. The value is taken from the HTTP "User-Agent" header.
_http_host - The host part of the URI, the client is using while communicating with Heimdall.
_http_scheme - The scheme part of the URI, the client is using while communicating with Heimdall.

If the request comes from an intermediary, like e.g. an API Gateway and heimdall is configured to trust that "proxy" (see trusted_proxies configuration of the Decision service, as well as the trusted_proxies configuration of the Proxy service), then following fields will be part of the events as well if the corresponding HTTP headers were sent.

_http_x_forwarded_proto - The value of the "X-Forwarded-Proto" header.
_http_x_forwarded_host - The value of the "X-Forwarded-Host" header.
_http_x_forwarded_path - The value of the "X-Forwarded-Path" header.
_http_x_forwarded_uri - The value of the "X-Forwarded-Uri" header.
_http_x_forwarded_for - The value of the "X-Forwarded-For" header.
_http_forwarded - The value of the "Forwarded" header.

Following are the fields, which are set in the transaction finalization event in addition:

_body_bytes_sent - The length of the response body.
_http_status_code - The numeric HTTP response status code
_tx_duration_ms - The duration of the transaction in milliseconds. If heimdall is operated in proxy mode, it will also include the time used to communicate with the upstream service.
_access_granted - Set either to true or false, indicating whether heimdall granted access or not.
_subject - The subject identifier if the access was granted.
error - The information about an error, which e.g. led to the denial of the request.

Following are the fields, which are set if tracing is enabled:

_trace_id - The trace id as defined by OpenTelemetry.
_span_id - The span id as defined by OpenTelemetry of the current transaction.
_parent_id - The span id of the callee, which started the given transaction. Only present if the callee set the corresponding tracing header.

If you configure Heimdall to log in text format, you can expect output as shown below:

2022-08-03T12:40:16+02:00 INF TX started _client_ip=127.0.0.1 _http_host=127.0.0.1:4468 _http_method=GET
 _http_path=/foo _http_scheme=http _http_user_agent=curl/7.74.0 _parent_id=3449bda63ed70206
 _span_id=f57c007257fee0ed _trace_id=00000000000000000a5af97bffe6a8a2 _tx_start=1659523216

....

2022-08-03T12:40:16+02:00 INF TX finished _access_granted=true _body_bytes_sent=0 _client_ip=127.0.0.1
 _http_host=127.0.0.1:4468 _http_method=GET _http_path=/foo _http_scheme=http _http_status_code=202
 _http_user_agent=curl/7.74.0 _subject=anonymous _parent_id=3449bda63ed70206 _span_id=f57c007257fee0ed
 _trace_id=00000000000000000a5af97bffe6a8a2 _tx_duration_ms=0 _tx_start=1659523216

Otherwise, if you configure it to use gelf format, the output will look as follows:

{"_level_name": "INFO", "version":"1.1", "host":"unknown", "_tx_start":1659523295,
 "_client_ip": "127.0.0.1", "_http_method": "GET", "_http_path":"/foo",
 "_http_user_agent": "curl/7.74.0", "_http_host": "127.0.0.1:4468", "_http_scheme": "http",
 "timestamp": 1659523295, "level": 6, "_parent_id": "3449bda63ed70206",
 "_span_id": "f57c007257fee0ed", "_trace_id": "00000000000000000a5af97bffe6a8a2",
 "short_message": "TX started"}

....

{"_level_name": "INFO", "version": "1.1", "host": "unknown", "_tx_start": 1659523295,
 "_client_ip": "127.0.0.1", "_http_method": "GET", "_http_path": "/foo",
 "_http_user_agent": "curl/7.74.0", "_http_host": "127.0.0.1:4468", "_http_scheme": "http",
 "_body_bytes_sent": 0, "_http_status_code":202, "_tx_duration_ms":0, "_subject": "anonymous",
 "_access_granted": true, "timestamp":1659523295, "level": 6, "_parent_id": "3449bda63ed70206",
 "_span_id": "f57c007257fee0ed", "_trace_id": "00000000000000000a5af97bffe6a8a2",
 "short_message": "TX finished"}

Tracing in Heimdall

Heimdall makes use of OpenTelemetry for distributed tracing to support recording of paths taken by requests and supports all environment variables including the defined values according to OpenTelemetry Environment Variable Specification. In addition to these environment variables, heimdall defines its own tracing options, which are described in Tracing Configuration and can be used to tune the behaviour.

Tracing is enabled by default.

On one hand, this chapter serves the purpose of a quick introduction to distributed tracing with heimdall and on the other hand to list the options that go beyond the standard OTEL definitions.

Tracing Context Propagation

When a request arrives at heimdall, it will create a trace context object based on the received headers, which according to OTEL are the traceparent and tracestate HTTP headers, defined in W3C Trace Context as well as baggage HTTP header, defined in W3C Baggage. The creation of that context, as well as the transformation of it into new HTTP headers, set by heimdall while communicating with further services is named propagation and the components responsible for the creation of such context object are named propagators.

Since not every service in a multi-service system may set or understand the above OTEL specific HTTP headers (as these might still be using tracing vendor specific headers), interoperability can be achieved by configuring the required propagators by making use of the OTEL_PROPAGATORS environment variable. OTEL defines the following values for this variable:

tracecontext - W3C Trace Context propagator. Enabled by default, if OTEL_PROPAGATORS is not set.
baggage - W3C Baggage propagator. Enabled by default if OTEL_PROPAGATORS is not set.
b3 - Zipkin B3 Single Header propagator.
b3multi - Zipkin B3 Multiple Header propagator.
jaeger - Jaeger Header propagator.
xray - AWS X-Ray Header propagator.
ottrace - OT Trace Header propagator.
none - No automatically configured propagator.

All of these are supported by heimdall. In addition, following propagators can be configured as well:

datadog - Datadog APM Trace Header propagator.^[1]

Configured propagators are used for inbound, as well as for outbound traffic.

Span Exporters

Span Exporter handle the delivery of spans to external receivers (collectors, or agents). This is the final component in the trace export pipeline and typically provided by the APM vendor, like Jaeger, Zipkin, Instana, etc. Since not every multi-service system may have an up to day telemetry receiver, which supports protocols defined by OTEL, interoperability can be achieved by configuring the required exporters by making use of the OTEL_TRACES_EXPORTER environment variable. OTEL defines the following values for this variable:

otlp - OTLP exporter. Enabled by default if OTEL_TRACES_EXPORTER is not set.
jaeger - Jaeger Thrift exporter to export spans in Jaeger data model.
zipkin - Zipkin exporter to export spans in Zipkin data model.
none - No automatically configured exporter for traces.

All of these are supported by heimdall. In addition, following exporters can be configured as well:

instana - Instana exporter to export spans in Instana data model.^[2]

Example Configuration

The environment variables set below configure heimdall to use Jaeger propagator and to export the spans via OTLP over grpc to the collector available under http://collector:4317.

OTEL_PROPAGATORS=jaeger
OTEL_TRACES_EXPORTER=otlp
OTEL_EXPORTER_OTLP_TRACES_PROTOCOL=grpc
OTEL_EXPORTER_OTLP_TRACES_ENDPOINT=http://collector:4317

If your environment supports OpenTelemetry and usage of defaults is ok, most probably, the only required environment variable to be set might be the OTEL_EXPORTER_OTLP_TRACES_ENDPOINT.

Metrics in Heimdall

See Metrics Configuration.

1. Datadog supports the OTLP protokoll. For that reason, there is no exporter available.

2. Instana supports the W3C header used by OTEL. For that reason, there is no propagator available.

Last updated on Oct 7, 2022

CLI

Security