diff --git a/.github/workflows/pr.yml b/.github/workflows/pr.yml index a2f1907..843d8e4 100644 --- a/.github/workflows/pr.yml +++ b/.github/workflows/pr.yml @@ -191,6 +191,22 @@ jobs: "http://127.0.0.1:8000/dims3/development/resize/100x100/?url=http://$origin/grid.png" docker exec dims-ci sh -c 'test -s /tmp/out.png' + # The metrics endpoint serves its own port, and only when the + # environment turns it on. + - name: Scrape the metrics endpoint + run: | + docker rm -f dims-ci + docker run -d --name dims-ci -p 8001:8001 \ + -e DIMS_METRICS_ENABLED=on mod-dims:ci + for i in $(seq 30); do + if curl -fsS -o /dev/null http://127.0.0.1:8001/metrics; then + break + fi + sleep 1 + done + curl -fsS http://127.0.0.1:8001/metrics | grep -q dims_requests_total + curl -fsS http://127.0.0.1:8001/metrics | grep -q dims_httpd_workers + # The runtime user must not be able to rewrite the module it runs. - name: Check the file permissions run: | diff --git a/CMakeLists.txt b/CMakeLists.txt index c6088fe..902d167 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -82,6 +82,8 @@ add_library(mod_dims MODULE src/signature.c src/svgguard.c src/url.c + src/metrics.c + src/metrics_report.c src/status.c src/mod_dims.c src/module.c diff --git a/docker/Dockerfile b/docker/Dockerfile index 616ddb4..e8a6e64 100644 --- a/docker/Dockerfile +++ b/docker/Dockerfile @@ -65,6 +65,7 @@ ENV DIMS_ALLOW_PRIVATE_ADDRESSES=off ENV DIMS_STATUS_VERBOSE=off ENV DIMS_ENABLE_DIMS3=off ENV DIMS_ENABLE_DIMS4=on +ENV DIMS_METRICS_ENABLED=off ENV DIMS_ENCRYPTION_ALGORITHM=AES/GCM/NoPadding ENV LC_ALL="C" @@ -105,7 +106,7 @@ RUN rm -rf /usr/local/apache2/build \ chown -R root:root /usr/local/apache2 /usr/local/imagemagick && \ chmod -R go-w /usr/local/apache2 /usr/local/imagemagick -EXPOSE 8000 +EXPOSE 8000 8001 USER 33 # A real request, not a configuration check. The status handler answers diff --git a/docker/README.md b/docker/README.md index 8272c10..0efe24f 100644 --- a/docker/README.md +++ b/docker/README.md @@ -36,6 +36,16 @@ $ docker run -e DIMS_SECRET=mysecret mod-dims:latest $ docker run -e DIMS_ENABLE_DIMS3=on -e DIMS_WHITELIST="images.pexels.com" mod-dims:latest ``` +## Set DIMS_METRICS_ENABLED to scrape the server + +```shell +$ docker run -p 8000:8000 -p 8001:8001 -e DIMS_METRICS_ENABLED=on mod-dims:latest +$ curl http://localhost:8001/metrics +``` + +Port 8001 serves `/metrics` and `/dims-status/`. Publish 8000 to callers and +keep 8001 for the monitoring network. + # Configuration | Environment Variables | Description | Default | @@ -45,6 +55,7 @@ $ docker run -e DIMS_ENABLE_DIMS3=on -e DIMS_WHITELIST="images.pexels.com" mod-d | `DIMS_WHITELIST` | Hosts /dims3/ may fetch from, separated by spaces. Empty matches no host. | "" | | `DIMS_ENABLE_DIMS3` | Whether the image serves /dims3/. It accepts an unsigned request, so the image ships it off. | off | | `DIMS_ENABLE_DIMS4` | Whether the image serves /dims4/. | on | +| `DIMS_METRICS_ENABLED` | Whether the image serves Prometheus metrics at `/metrics` on port 8001. | off | | `DIMS_DEFAULT_IMAGE_URL` | URL to the image sent when a request fails. A single dash means none. | "-" | | `DIMS_SECRET` | Shared secret for /dims4/ signatures. A single dash means none, and /dims4/ then refuses every request. | "-" | | `DIMS_DOWNLOAD_TIMEOUT` | Max time allowed for downloading source images, in milliseconds. | 60000 | diff --git a/docker/dims.conf b/docker/dims.conf index 749a847..f64c3b4 100644 --- a/docker/dims.conf +++ b/docker/dims.conf @@ -87,3 +87,23 @@ DimsAddWhitelist ${DIMS_WHITELIST} SetHandler dims-status + +# The metrics listener. A Service exposes 8000 and a scrape targets 8001, so +# no ingress route reaches /metrics. Behind an ingress controller httpd reads +# the controller address rather than the caller address, so a second listener +# moves the decision to the network. +# +# /dims-status/ serves both ports, because the health check reads it on 8000. +Listen 8001 + +DimsMetricsEnabled ${DIMS_METRICS_ENABLED} + + + + SetHandler dims-metrics + + + + SetHandler dims-status + + diff --git a/docs/docs/configuration/index.md b/docs/docs/configuration/index.md index 11fc19b..a0636d5 100644 --- a/docs/docs/configuration/index.md +++ b/docs/docs/configuration/index.md @@ -71,6 +71,7 @@ Two more are worth enabling as your deployment allows. | `DimsImagemagickMemorySize` | 512 | | `DimsImagemagickTimeout` | 3000 | | `DimsIncludeDisposition` | false | +| `DimsMetricsEnabled` | `Off` | | `DimsMaxSourceBytes` | 0 | | `DimsNoImageCacheExpire` | 60 | | `DimsOptimizeResize` | 0 | diff --git a/docs/docs/configuration/metrics.md b/docs/docs/configuration/metrics.md new file mode 100644 index 0000000..3dffd99 --- /dev/null +++ b/docs/docs/configuration/metrics.md @@ -0,0 +1,33 @@ +# Metrics + +## DimsMetricsEnabled + +```apacheconf +DimsMetricsEnabled on +``` + +Whether the module serves [`/metrics`](/endpoints/metrics). Default `Off`. + +The directive is the switch, and a `` names the path. Both are +needed: + +```apacheconf +DimsMetricsEnabled on + + + SetHandler dims-metrics + +``` + +With the directive `Off` the handler declines the request and httpd answers +404, so a configuration that keeps the location stops publishing when the +directive goes off. + +The container reads `DIMS_METRICS_ENABLED`. The image sets it to `off`. It +serves metrics on port 8001. + +:::note +The endpoint reports the counters, the uptime, and the library versions. Serve +it on a port your callers cannot reach, or restrict the location to your +monitoring host. `DimsStatusVerbose Off` drops the version labels. +::: diff --git a/docs/docs/endpoints/dims3.md b/docs/docs/endpoints/dims3.md index 2c9e406..0167fab 100644 --- a/docs/docs/endpoints/dims3.md +++ b/docs/docs/endpoints/dims3.md @@ -19,6 +19,11 @@ any image, so the host allowlist is what decides which images are reachable. It reads the same query parameters as [`/dims4/`](/endpoints/dims4), apart from the signature. +The `client` segment is a legacy of `/dims3/` and `/dims4/`. +[`/dims5/`](/endpoints/dims5) dropped it. A server that serves several clients +gives each its own ``, which separates the clients, the allowlist, +and the keys. + ## The allowlist [`DimsAddWhitelist`](/configuration/image-sources) lists the hosts an image may diff --git a/docs/docs/endpoints/dims4.md b/docs/docs/endpoints/dims4.md index d95d5de..c75aaf0 100644 --- a/docs/docs/endpoints/dims4.md +++ b/docs/docs/endpoints/dims4.md @@ -18,6 +18,11 @@ neither can be changed without the secret. | `expires` | when the URL stops working, in seconds since the epoch | | `commands` | the [operations](/operations/) to run | +The `client` segment is a legacy of `/dims3/` and `/dims4/`. +[`/dims5/`](/endpoints/dims5) dropped it. A server that serves several clients +gives each its own ``, which separates the clients, the allowlist, +and the keys. + ## Query parameters | Name | Meaning | diff --git a/docs/docs/endpoints/index.md b/docs/docs/endpoints/index.md index 7523a3e..2868f41 100644 --- a/docs/docs/endpoints/index.md +++ b/docs/docs/endpoints/index.md @@ -1,6 +1,6 @@ # Endpoints -Four handlers, each set on a location. +Five handlers, each set on a location. | Handler | URL | Checked by | |---|---|---| @@ -8,6 +8,7 @@ Four handlers, each set on a location. | [`dims4`](/endpoints/dims4) | `/dims4/////?url=` | a signature | | [`dims3`](/endpoints/dims3) | `/dims3///?url=` | the host allowlist | | [`dims-status`](/endpoints/status) | `/dims-status/` | nothing | +| [`dims-metrics`](/endpoints/metrics) | `/metrics` | nothing | | [`dims-local`](/endpoints/local) | a file on disk | nothing | `/dims5/` is the one to use. Its signature covers the commands, the image URL, diff --git a/docs/docs/endpoints/metrics.md b/docs/docs/endpoints/metrics.md new file mode 100644 index 0000000..26f84a5 --- /dev/null +++ b/docs/docs/endpoints/metrics.md @@ -0,0 +1,189 @@ +# /metrics + +``` +/metrics +``` + +Reports the module, ImageMagick, and httpd in the Prometheus text format. A +Prometheus server scrapes it, and so does an OpenTelemetry Collector through +its `prometheus` receiver. + +Two lines turn it on. The directive is the switch, and the location names the +path. + +```apacheconf +DimsMetricsEnabled on + + + SetHandler dims-metrics + +``` + +[`DimsMetricsEnabled`](/configuration/metrics) defaults to `Off`, so a server +that upgrades publishes no metrics until an operator turns it on. + +## What it reports + +``` +# HELP dims_requests_total Requests by endpoint and outcome. +# TYPE dims_requests_total counter +dims_requests_total{endpoint="dims5",outcome="success"} 18423 +dims_requests_total{endpoint="dims5",outcome="download_timeout"} 4 + +# HELP dims_request_duration_seconds Time to serve a request. +# TYPE dims_request_duration_seconds histogram +dims_request_duration_seconds_bucket{endpoint="dims5",le="0.025"} 17155 +dims_request_duration_seconds_bucket{endpoint="dims5",le="+Inf"} 18427 +dims_request_duration_seconds_sum{endpoint="dims5"} 314.288000 +dims_request_duration_seconds_count{endpoint="dims5"} 18427 +``` + +| Metric | Type | Labels | +|---|---|---| +| `dims_requests_total` | counter | `endpoint`, `outcome` | +| `dims_responses_total` | counter | `endpoint`, `code` | +| `dims_requests_in_flight` | gauge | `endpoint` | +| `dims_request_duration_seconds` | histogram | `endpoint` | +| `dims_source_fetch_duration_seconds` | histogram | | +| `dims_source_bytes` | histogram | | +| `dims_source_bytes_total` | counter | | +| `dims_source_format_total` | counter | `format` | +| `dims_origin_responses_total` | counter | `code` | +| `dims_imagemagick_duration_seconds` | histogram | | +| `dims_source_frames` | histogram | | +| `dims_output_bytes` | histogram | | +| `dims_output_bytes_total` | counter | | +| `dims_output_format_total` | counter | `format` | +| `dims_source_fetch_total` | counter | `result` | +| `dims_source_fetch_errors_total` | counter | `code` | +| `dims_netguard_refusals_total` | counter | `reason` | +| `dims_allowlist_checks_total` | counter | `mode`, `result` | +| `dims_signature_checks_total` | counter | `endpoint`, `result` | +| `dims_eurl_decrypt_total` | counter | `result` | +| `dims_operations_total` | counter | `operation`, `trigger` | +| `dims_operation_failures_total` | counter | `operation` | +| `dims_operation_duration_seconds` | histogram | `operation` | +| `dims_imagemagick_exceptions_total` | counter | `kind`, `severity` | +| `dims_overlay_cache_lookups_total` | counter | `result` | +| `dims_overlay_cache_evictions_total` | counter | | +| `dims_error_images_total` | counter | `source` | +| `dims_error_image_failures_total` | counter | | +| `dims_imagemagick_resource_bytes` | gauge | `resource` | +| `dims_imagemagick_resource_max_bytes` | gauge | `resource` | +| `dims_imagemagick_resource_limit_bytes` | gauge | `resource` | +| `dims_process_resident_bytes` | gauge | | +| `dims_process_resident_max_bytes` | gauge | | +| `dims_process_virtual_bytes` | gauge | | +| `dims_workers` | gauge | | +| `dims_httpd_workers` | gauge | `state` | +| `dims_httpd_processes` | gauge | | +| `dims_httpd_processes_limit` | gauge | | +| `dims_httpd_threads_per_process` | gauge | | +| `dims_httpd_connections` | gauge | `state` | +| `dims_httpd_generation` | gauge | | + +`endpoint` holds `dims3`, `dims4`, `dims5`, or `local`. + +`outcome` holds `success`, `failure`, `download_timeout`, +`imagemagick_timeout`, `bad_client`, `bad_url`, `bad_arguments`, +`hostname_not_in_whitelist`, `file_not_found`, or `network_refused`. + +`code` holds `200`, `400`, `403`, `404`, `429`, `500`, `502`, `503`, `504`, or +`other`. The list bounds the label, because +[`DimsOriginStatusMode`](/configuration/cache-control) `forward` reports the +status the origin returned. + +`format` holds `jpeg`, `png`, `gif`, `webp`, `avif`, `heic`, `tiff`, `svg`, or +`other`. + +`resource` holds `area`, `memory`, `map`, or `disk`. + +`result` on `dims_source_fetch_total` holds `ok`, `timeout`, +`transport_error`, `refused`, or `http_error`. `code` on +`dims_source_fetch_errors_total` holds a libcurl name such as +`couldnt_resolve_host` or `ssl_connect_error`, and `other` for the rest. + +`reason` holds `bad_scheme`, `bad_url`, `reserved_address`, +`private_address`, `host_not_allowed`, or `too_many_redirects`. + +`mode` holds `skip`, `log`, or `enforce`. Under +[`DimsAllowlistSigned`](/configuration/image-sources) `log` the module records +what enforcing would refuse and serves the request, so +`dims_allowlist_checks_total{mode="log",result="refused"}` is the number to +watch before setting `enforce`. + +`result` on a signature holds `ok`, `mismatch`, `expired`, `too_far_future`, +`missing_key`, or `bad_client`. + +`operation` holds one of the seventeen command names. `trigger` holds +`request` or `default`. `strip` runs when the command list holds none, and +`format` runs under [`DimsDefaultOutputFormat`](/configuration/output), so +both report `default`. + +`kind` holds an ImageMagick exception kind such as `resource_limit`, +`corrupt_image`, or `policy`. `severity` holds `warning`, `error`, or +`fatal`. + +`source` on an error image holds `drawn` for +[`DimsErrorBackground`](/configuration/cache-control), `fetched` for +[`DimsDefaultImageURL`](/configuration/cache-control), or `none`. + +## The whole server + +Every metric describes the server, with no `client` label. The client id is a +legacy of `/dims3/` and `/dims4/`, and `/dims5/` dropped it. + +A deployment that serves several clients gives each its own ``, +which separates the clients, the allowlist, and the keys. The counters stay +shared, because the module creates one block for the process. Separate metrics +need separate instances. + +## Per process and per server + +Most metrics come from a block every worker adds to, so they describe the whole +server. + +`dims_imagemagick_resource_bytes`, `dims_process_resident_bytes`, and +`dims_process_virtual_bytes` are per worker. Each child writes its own numbers +when a request ends, and this endpoint sums the live workers. The matching +`_max_bytes` gauge reports the widest single worker, so one worker at its +ceiling is visible beside three idle ones. `dims_workers` counts the workers in +the sum. + +`dims_process_resident_bytes` and `dims_process_virtual_bytes` read +`/proc/self/statm`. A platform without it omits both. + +## Kubernetes + +The container serves images on 8000 and metrics on 8001, so a Service exposes +8000 and a scrape targets 8001. + +```shell +docker run -p 8000:8000 -p 8001:8001 -e DIMS_METRICS_ENABLED=on \ + ghcr.io/beetlebugorg/mod_dims:latest +``` + +An OpenTelemetry Collector reads it through the `prometheus` receiver: + +```yaml +receivers: + prometheus: + config: + scrape_configs: + - job_name: mod_dims + static_configs: + - targets: ['mod-dims:8001'] +``` + +## Worker headroom + +`dims_httpd_workers{state="ready"}` against `dims_httpd_processes_limit` times +`dims_httpd_threads_per_process` is the headroom the pool has left. Ready +workers near zero while `dims_requests_in_flight` climbs means the pool is +full. + +:::note +`dims_build_info` names the mod_dims, ImageMagick, and libcurl versions. +[`DimsStatusVerbose`](/configuration/output) `Off` drops it, the same way it +drops the version lines from [`/dims-status/`](/endpoints/status). +::: diff --git a/docs/sidebars.js b/docs/sidebars.js index 8b047c6..ef24be0 100644 --- a/docs/sidebars.js +++ b/docs/sidebars.js @@ -7,7 +7,7 @@ const sidebars = { type: 'category', label: 'Endpoints', link: {type: 'doc', id: 'endpoints/index'}, - items: ['endpoints/dims5', 'endpoints/dims4', 'endpoints/dims3', 'endpoints/status', 'endpoints/local'], + items: ['endpoints/dims5', 'endpoints/dims4', 'endpoints/dims3', 'endpoints/status', 'endpoints/metrics', 'endpoints/local'], }, { type: 'category', @@ -60,6 +60,7 @@ const sidebars = { 'configuration/cache-control', 'configuration/output', 'configuration/resources', + 'configuration/metrics', ], }, ], diff --git a/src/configuration.c b/src/configuration.c index 095a547..7e779cb 100644 --- a/src/configuration.c +++ b/src/configuration.c @@ -54,6 +54,10 @@ dims_create_config(apr_pool_t *p, server_rec *s) config->origin_status_mode = DIMS_ORIGIN_STATUS_FORWARD; config->status_verbose = 1; + /* Off, so a server that upgrades publishes no metrics until an operator + * turns it on. */ + config->metrics_enabled = 0; + /* The cache holds fetched overlays, and an evicted one is fetched again, * so a bound costs a caller nothing. */ config->overlay_cache_max_entries = 1024; @@ -352,6 +356,15 @@ dims_config_set_allow_private_addresses(cmd_parms *cmd, void *dummy, int arg) return NULL; } +static const char * +dims_config_set_metrics_enabled(cmd_parms *cmd, void *dummy, int arg) +{ + dims_config_rec *config = (dims_config_rec *) ap_get_module_config( + cmd->server->module_config, &dims_module); + config->metrics_enabled = arg; + return NULL; +} + static const char * dims_config_set_allowlist_signed(cmd_parms *cmd, void *dummy, const char *arg) { @@ -625,6 +638,10 @@ const command_rec dims_directives[] = "to report the status the origin returned, or map to report " "404 for a missing source, 504 for a timeout, and 502 for " "every other origin failure. The default is forward."), + AP_INIT_FLAG("DimsMetricsEnabled", + dims_config_set_metrics_enabled, NULL, RSRC_CONF, + "Whether the module serves metrics at a location that sets " + "the dims-metrics handler. The default is Off."), AP_INIT_FLAG("DimsStatusVerbose", dims_config_set_status_verbose, NULL, RSRC_CONF, "Whether the status handler prints the mod_dims, ImageMagick, " diff --git a/src/dims5.c b/src/dims5.c index d12222d..4ef57d1 100644 --- a/src/dims5.c +++ b/src/dims5.c @@ -6,6 +6,7 @@ */ #include "dims5.h" +#include "metrics.h" #include "encryption.h" #include "signature.h" #include "url.h" @@ -92,11 +93,13 @@ dims5_verify(dims_request_rec *d) decrypted = aes_128_gcm_decrypt(d->r, derived, (unsigned char *) eurl); if (decrypted == NULL) { + dims_metrics_eurl(0); ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "Cannot decrypt eurl, on request: %s", d->r->uri); return DIMS_BAD_URL; } + dims_metrics_eurl(1); image_url = decrypted; } else { image_url = query_value(d, "url"); @@ -123,11 +126,14 @@ dims5_verify(dims_request_rec *d) dims_signed_query(d->pool, d->r->args))); if (expected == NULL || !dims_signature_equal(expected, signature)) { + dims_metrics_signature(DIMS_ENDPOINT_DIMS5, DIMS_SIG_MISMATCH); ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "Signature mismatch, on request: %s", d->r->uri); return DIMS_BAD_URL; } + dims_metrics_signature(DIMS_ENDPOINT_DIMS5, DIMS_SIG_OK); + d->image_url = image_url; d->unparsed_commands = commands; d->client_id = NULL; diff --git a/src/handler.c b/src/handler.c index 0e34cbb..a6ad5dd 100644 --- a/src/handler.c +++ b/src/handler.c @@ -13,6 +13,7 @@ #include "url.h" #include "dims5.h" #include "encryption.h" +#include "metrics.h" #include "status.h" #include "pipeline.h" @@ -47,6 +48,7 @@ dims_handle_request(dims_request_rec *d) if(!(d->client_config = apr_hash_get(d->config->clients, d->client_id, APR_HASH_KEY_STRING))) { + dims_metrics_signature(d->endpoint, DIMS_SIG_BAD_CLIENT); return dims_cleanup(d, "Application ID is not valid", DIMS_BAD_CLIENT); } @@ -67,11 +69,13 @@ dims_handle_request(dims_request_rec *d) now = apr_time_sec(now_time); if ( expires - now < 0 ) { ap_log_rerror( APLOG_MARK, APLOG_DEBUG,0, d->r, "Image expired: %s now=%ld", d->r->uri,now); + dims_metrics_signature(d->endpoint, DIMS_SIG_EXPIRED); return dims_cleanup( d, "Image Key has expired", DIMS_BAD_URL); } if ( expires - now > d->config->max_expiry_period && d->config->max_expiry_period >0 ) { ap_log_rerror( APLOG_MARK, APLOG_DEBUG,0, d->r, "Image expiry too far in the future:%s %s now=%ld",expires_str, d->r->uri,now); + dims_metrics_signature(d->endpoint, DIMS_SIG_TOO_FAR_FUTURE); return dims_cleanup(d, "Image key too far in the future", DIMS_BAD_URL); } @@ -116,6 +120,7 @@ dims_handle_request(dims_request_rec *d) if (d->client_config->secret_key == NULL) { ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "Developer key not set for client '%s'", d->client_config->id); + dims_metrics_signature(d->endpoint, DIMS_SIG_MISSING_KEY); return dims_cleanup(d, "Missing Developer Key", DIMS_BAD_CLIENT); } @@ -144,8 +149,10 @@ dims_handle_request(dims_request_rec *d) gen_hash[7] = '\0'; ap_log_rerror(APLOG_MARK, APLOG_DEBUG,0, d->r, "Key Mismatch: wanted %6s got %6s [%s?url=%s]", gen_hash, hash, d->r->uri, d->image_url); + dims_metrics_signature(d->endpoint, DIMS_SIG_MISMATCH); return dims_cleanup(d, "Key mismatch", DIMS_BAD_URL); } + dims_metrics_signature(d->endpoint, DIMS_SIG_OK); ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "secret key (%s) to validated (%s:%s)", hash, d->unparsed_commands,d->image_url); } @@ -256,6 +263,11 @@ dims_handle_request(dims_request_rec *d) found = 1; } else { found = dims_host_allowed(d->config->whitelist, hostname); + + /* This check refuses the request, so it counts as enforce. The + * guard runs its own check at fetch time under + * DimsAllowlistSigned. */ + dims_metrics_allowlist(DIMS_ALLOWLIST_ENFORCE, found); } if(found) { @@ -357,6 +369,11 @@ dims_handler(request_rec *r) d->client_config = NULL; d->no_image_url = d->config->no_image_url; d->use_no_image = 0; + d->endpoint = -1; + d->source_format_index = -1; + d->output_format_index = -1; + d->output_bytes = 0; + d->source_frames = 0; d->image_url = NULL; d->filename = NULL; d->cache_control = NULL; @@ -390,6 +407,8 @@ dims_handler(request_rec *r) /* Handle local filesystem images w/DIMS parameters. */ d->filename = r->canonical_filename; d->unparsed_commands = r->path_info; + d->endpoint = DIMS_ENDPOINT_LOCAL; + dims_metrics_request_begin(d); return dims_handle_request(d); } else if ((strcmp(r->handler, "dims3") == 0) || @@ -398,6 +417,9 @@ dims_handler(request_rec *r) char *p, *fixed_url = NULL, *commands = NULL, *eurl = NULL; int is_dims4 = strcmp(r->handler, "dims4") == 0; + d->endpoint = is_dims4 ? DIMS_ENDPOINT_DIMS4 : DIMS_ENDPOINT_DIMS3; + dims_metrics_request_begin(d); + if (is_dims4) { d->use_secret_key = 1; } @@ -545,8 +567,12 @@ dims_handler(request_rec *r) return dims_handle_request(d); } else if(strcmp(r->handler, "dims5") == 0) { d->scheme = DIMS_SCHEME_DIMS5; + d->endpoint = DIMS_ENDPOINT_DIMS5; + dims_metrics_request_begin(d); return dims_handle_request(d); + } else if(strcmp(r->handler, "dims-metrics") == 0) { + return dims_metrics_handler(r); } else if(strcmp(r->handler, "dims-status") == 0) { return dims_status_handler(r); } else if(strcmp(r->handler, "dims-sizer") == 0) { diff --git a/src/metrics.c b/src/metrics.c new file mode 100644 index 0000000..c48ef02 --- /dev/null +++ b/src/metrics.c @@ -0,0 +1,741 @@ +/* + * The metrics block, shared by every worker. + * + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "metrics.h" +#include "module.h" + +#include + +#include + +#include +#include +#include + +dims_metrics_rec *dims_metrics; + +static apr_shm_t *metrics_shm; + +/* The slot this child claimed in dims_metrics_child_init. */ +static dims_process_rec *my_process; + +static const double duration_bound[] = { + 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10 +}; + +static const double byte_bound[] = { + 16384, 65536, 262144, 1048576, 4194304, 16777216, 67108864 +}; + +static const double frame_bound[] = { + 1, 2, 4, 8, 16, 32, 64, 128 +}; + +const dims_bucket_spec dims_duration_buckets = { + duration_bound, (int) (sizeof(duration_bound) / sizeof(duration_bound[0])) +}; + +const dims_bucket_spec dims_byte_buckets = { + byte_bound, (int) (sizeof(byte_bound) / sizeof(byte_bound[0])) +}; + +const dims_bucket_spec dims_frame_buckets = { + frame_bound, (int) (sizeof(frame_bound) / sizeof(frame_bound[0])) +}; + +/* Indexed by dims_endpoint_t. */ +static const char *const endpoint_name[] = { + "dims3", "dims4", "dims5", "local" +}; + +/* Indexed by dims_status_t, which starts at DIMS_SUCCESS. */ +static const char *const outcome_name[DIMS_OUTCOME_COUNT] = { + "success", + "failure", + "download_timeout", + "imagemagick_timeout", + "bad_client", + "bad_url", + "bad_arguments", + "hostname_not_in_whitelist", + "file_not_found", + "network_refused" +}; + +/* 304 answers a conditional request, so a caching client sees it often. */ +static const int code_value[DIMS_CODE_COUNT - 1] = { + 200, 304, 400, 403, 404, 429, 500, 502, 503, 504 +}; + +static const char *const code_name[DIMS_CODE_COUNT] = { + "200", "304", "400", "403", "404", "429", "500", "502", "503", "504", + "other" +}; + +static const int origin_code_value[DIMS_ORIGIN_CODE_COUNT - 1] = { + 200, 301, 302, 304, 400, 403, 404, 429, 500, 502, 503, 504 +}; + +static const char *const origin_code_name[DIMS_ORIGIN_CODE_COUNT] = { + "200", "301", "302", "304", "400", "403", "404", "429", + "500", "502", "503", "504", "other" +}; + +static const char *const format_name[DIMS_FORMAT_COUNT] = { + "jpeg", "png", "gif", "webp", "avif", "heic", "tiff", "svg", "other" +}; + +apr_status_t +dims_metrics_init(apr_pool_t *p, server_rec *s) +{ + apr_status_t status; + apr_size_t size; + int daemons = 0; + + if (ap_mpm_query(AP_MPMQ_HARD_LIMIT_DAEMONS, &daemons) != APR_SUCCESS || + daemons < 1) { + daemons = 1; + } + + size = sizeof(dims_metrics_rec) + + ((apr_size_t) daemons * sizeof(dims_process_rec)); + + status = apr_shm_create(&metrics_shm, size, NULL, p); + if (status != APR_SUCCESS) { + ap_log_error(APLOG_MARK, APLOG_ERR, status, s, + "mod_dims: the metrics block was not created"); + return status; + } + + dims_metrics = apr_shm_baseaddr_get(metrics_shm); + if (dims_metrics == NULL) { + ap_log_error(APLOG_MARK, APLOG_ERR, 0, s, + "mod_dims: the metrics block has no address"); + return APR_EGENERAL; + } + + memset(dims_metrics, 0, size); + dims_metrics->process_slots = (apr_uint32_t) daemons; + + ap_log_error(APLOG_MARK, APLOG_INFO, 0, s, + "mod_dims: the metrics block is %" APR_SIZE_T_FMT " bytes, " + "with %d process slots", size, daemons); + + return APR_SUCCESS; +} + +void +dims_metrics_child_init(void) +{ + apr_uint32_t i; + apr_uint64_t pid; + + if (dims_metrics == NULL) { + return; + } + + pid = (apr_uint64_t) getpid(); + + /* The first slot holding zero, or a slot left by a child that died. A + * losing compare and swap means another child took it, so try the next. */ + for (i = 0; i < dims_metrics->process_slots; i++) { + dims_process_rec *slot = &dims_metrics->process[i]; + + if (apr_atomic_cas32((apr_uint32_t *) &slot->pid, (apr_uint32_t) pid, + 0) == 0) { + slot->resident_bytes = 0; + slot->virtual_bytes = 0; + memset(slot->imagemagick_resource, 0, + sizeof(slot->imagemagick_resource)); + my_process = slot; + return; + } + } +} + +dims_process_rec * +dims_metrics_process(void) +{ + return my_process; +} + +int +dims_metrics_outcome_index(int status) +{ + if (status < DIMS_SUCCESS || status >= DIMS_OUTCOME_COUNT) { + return DIMS_OUTCOME_COUNT - 1; + } + + return status; +} + +int +dims_metrics_code_index(int code) +{ + int i; + + for (i = 0; i < DIMS_CODE_COUNT - 1; i++) { + if (code_value[i] == code) { + return i; + } + } + + return DIMS_CODE_COUNT - 1; +} + +int +dims_metrics_origin_code_index(int code) +{ + int i; + + for (i = 0; i < DIMS_ORIGIN_CODE_COUNT - 1; i++) { + if (origin_code_value[i] == code) { + return i; + } + } + + return DIMS_ORIGIN_CODE_COUNT - 1; +} + +int +dims_metrics_format_index(const char *format) +{ + int i; + + if (format == NULL) { + return DIMS_FORMAT_COUNT - 1; + } + + /* ImageMagick reports JPG for a JPEG, and the two name one format. */ + if (strcasecmp(format, "jpg") == 0) { + return 0; + } + + for (i = 0; i < DIMS_FORMAT_COUNT - 1; i++) { + if (strcasecmp(format_name[i], format) == 0) { + return i; + } + } + + return DIMS_FORMAT_COUNT - 1; +} + +const char * +dims_metrics_endpoint_name(int index) +{ + if (index < 0 || index >= DIMS_ENDPOINT_COUNT) { + return ""; + } + + return endpoint_name[index]; +} + +const char * +dims_metrics_outcome_name(int index) +{ + if (index < 0 || index >= DIMS_OUTCOME_COUNT) { + return ""; + } + + return outcome_name[index]; +} + +const char * +dims_metrics_code_name(int index) +{ + if (index < 0 || index >= DIMS_CODE_COUNT) { + return ""; + } + + return code_name[index]; +} + +const char * +dims_metrics_origin_code_name(int index) +{ + if (index < 0 || index >= DIMS_ORIGIN_CODE_COUNT) { + return ""; + } + + return origin_code_name[index]; +} + +const char * +dims_metrics_format_name(int index) +{ + if (index < 0 || index >= DIMS_FORMAT_COUNT) { + return ""; + } + + return format_name[index]; +} + +int +dims_metrics_bucket_index(const dims_bucket_spec *spec, double value) +{ + int i; + + for (i = 0; i < spec->bounds; i++) { + if (value <= spec->bound[i]) { + return i; + } + } + + return spec->bounds; +} + +void +dims_metrics_observe(dims_histogram_rec *h, const dims_bucket_spec *spec, + apr_uint64_t value) +{ + double scaled = (spec == &dims_duration_buckets) + ? (double) value / 1000000.0 + : (double) value; + + apr_atomic_inc64(&h->bucket[dims_metrics_bucket_index(spec, scaled)]); + apr_atomic_add64(&h->sum, value); + apr_atomic_inc64(&h->count); +} + + +/* + * The end of a request, reached through a pool cleanup so that every return + * path in the handler records exactly once. + */ +static apr_status_t +record_request(void *baton) +{ + dims_request_rec *d = (dims_request_rec *) baton; + dims_metrics_rec *m = dims_metrics; + int endpoint = d->endpoint; + apr_uint64_t micros; + + if (m == NULL || endpoint < 0 || endpoint >= DIMS_ENDPOINT_COUNT) { + return APR_SUCCESS; + } + + apr_atomic_dec64(&m->in_flight[endpoint]); + + apr_atomic_inc64(&m->requests[endpoint] + [dims_metrics_outcome_index(d->status)]); + apr_atomic_inc64(&m->responses[endpoint] + [dims_metrics_code_index(d->r->status)]); + + micros = (apr_uint64_t) (apr_time_now() - d->start_time); + dims_metrics_observe(&m->request_duration[endpoint], &dims_duration_buckets, + micros); + + /* + * The source, when the request reached one. fetch_http_status names a + * source fetch, and download_time alone names an error image fetch. + * download_time counts milliseconds, so a fetch inside one millisecond + * reports zero and belongs in the first bucket. + */ + if (d->fetch_http_status != 0 || d->download_time > 0) { + dims_metrics_observe(&m->download_duration, &dims_duration_buckets, + (apr_uint64_t) d->download_time * 1000); + } + + if (d->original_image_size > 0) { + apr_atomic_add64(&m->source_bytes_total, + (apr_uint64_t) d->original_image_size); + dims_metrics_observe(&m->source_bytes, &dims_byte_buckets, + (apr_uint64_t) d->original_image_size); + } + + if (d->fetch_http_status != 0) { + apr_atomic_inc64(&m->origin_responses[ + dims_metrics_origin_code_index(d->fetch_http_status)]); + } + + if (d->source_format_index >= 0) { + apr_atomic_inc64(&m->source_format[d->source_format_index]); + } + + if (d->source_frames > 0) { + dims_metrics_observe(&m->source_frames, &dims_frame_buckets, + d->source_frames); + } + + /* ImageMagick ran when it timed the work, whatever the outcome. */ + if (d->imagemagick_time > 0) { + dims_metrics_observe(&m->imagemagick_duration, &dims_duration_buckets, + (apr_uint64_t) d->imagemagick_time * 1000); + } + + dims_metrics_sample_process(); + + /* The response, when one was written. */ + if (d->output_format_index >= 0) { + apr_atomic_inc64(&m->output_format[d->output_format_index]); + apr_atomic_add64(&m->output_bytes_total, d->output_bytes); + dims_metrics_observe(&m->output_bytes, &dims_byte_buckets, + d->output_bytes); + } + + return APR_SUCCESS; +} + +void +dims_metrics_request_begin(dims_request_rec *d) +{ + if (dims_metrics == NULL || d->endpoint < 0 || + d->endpoint >= DIMS_ENDPOINT_COUNT) { + return; + } + + apr_atomic_inc64(&dims_metrics->in_flight[d->endpoint]); + + apr_pool_cleanup_register(d->r->pool, d, record_request, + apr_pool_cleanup_null); +} + +/* + * The four ImageMagick resources the module limits, in the order the exposition + * writer prints them. + */ +static const ResourceType resource_type[4] = { + AreaResource, MemoryResource, MapResource, DiskResource +}; + +void +dims_metrics_sample_process(void) +{ + dims_process_rec *slot = my_process; + FILE *statm; + unsigned long resident = 0; + unsigned long virtual = 0; + int i; + + if (slot == NULL) { + return; + } + + for (i = 0; i < 4; i++) { + slot->imagemagick_resource[i] = + (apr_uint64_t) MagickGetResource(resource_type[i]); + } + + /* + * The first two fields of statm are the virtual size and the resident set, + * both in pages. The file is Linux only, so a platform without it reports + * zero and the writer omits the two gauges. + */ + statm = fopen("/proc/self/statm", "r"); + if (statm == NULL) { + return; + } + + if (fscanf(statm, "%lu %lu", &virtual, &resident) == 2) { + long page = sysconf(_SC_PAGESIZE); + + slot->virtual_bytes = (apr_uint64_t) virtual * (apr_uint64_t) page; + slot->resident_bytes = (apr_uint64_t) resident * (apr_uint64_t) page; + } + + fclose(statm); +} + +/* libcurl codes reported by name. The rest count under "other". */ +static const int curl_code_value[DIMS_CURL_CODE_COUNT - 1] = { + CURLE_OPERATION_TIMEDOUT, + CURLE_COULDNT_RESOLVE_HOST, + CURLE_COULDNT_CONNECT, + CURLE_SSL_CONNECT_ERROR, + CURLE_TOO_MANY_REDIRECTS, + CURLE_RECV_ERROR, + CURLE_SEND_ERROR, + CURLE_PARTIAL_FILE +}; + +static const char *const curl_code_name[DIMS_CURL_CODE_COUNT] = { + "operation_timedout", "couldnt_resolve_host", "couldnt_connect", + "ssl_connect_error", "too_many_redirects", "recv_error", "send_error", + "partial_file", "other" +}; + +static const char *const fetch_result_name[DIMS_FETCH_RESULT_COUNT] = { + "ok", "timeout", "transport_error", "refused", "http_error" +}; + +/* Indexed by dims_net_result, which starts at DIMS_NET_BAD_SCHEME. */ +static const char *const net_reason_name[DIMS_NET_REASON_COUNT] = { + "bad_scheme", "bad_url", "reserved_address", "private_address", + "host_not_allowed", "too_many_redirects" +}; + +static const char *const sig_result_name[DIMS_SIG_RESULT_COUNT] = { + "ok", "mismatch", "expired", "too_far_future", "missing_key", "bad_client" +}; + +/* The order dims_module.c registers them in the ops hash. */ +static const char *const operation_name[DIMS_OP_COUNT] = { + "strip", "resize", "crop", "thumbnail", "legacy_thumbnail", "legacy_crop", + "quality", "sharpen", "format", "brightness", "flipflop", "sepia", + "grayscale", "autolevel", "rotate", "invert", "watermark" +}; + +static const char *const exception_kind_name[DIMS_EXC_KIND_COUNT] = { + "blob", "cache", "coder", "configure", "corrupt_image", "delegate", + "draw", "file_open", "filter", "image", "missing_delegate", "module", + "monitor", "option", "policy", "random", "registry", "resource_limit", + "stream", "type", "wand", "other" +}; + +static const char *const exception_severity_name[DIMS_EXC_SEVERITY_COUNT] = { + "warning", "error", "fatal" +}; + +int +dims_metrics_curl_code_index(int code) +{ + int i; + + for (i = 0; i < DIMS_CURL_CODE_COUNT - 1; i++) { + if (curl_code_value[i] == code) { + return i; + } + } + + return DIMS_CURL_CODE_COUNT - 1; +} + +int +dims_metrics_operation_index(const char *operation) +{ + int i; + + if (operation == NULL) { + return -1; + } + + for (i = 0; i < DIMS_OP_COUNT; i++) { + if (strcmp(operation_name[i], operation) == 0) { + return i; + } + } + + return -1; +} + +/* + * ImageMagick names an exception by a kind and a severity in one enum, such as + * ResourceLimitError. The two are separate signals: a warning about a coder + * and a fatal cache failure read differently. + */ +void +dims_metrics_exception_slot(int exception_type, int *kind, int *severity) +{ + struct { int warning; int kind; } table[] = { + { BlobWarning, 0 }, + { CacheWarning, 1 }, + { CoderWarning, 2 }, + { ConfigureWarning, 3 }, + { CorruptImageWarning, 4 }, + { DelegateWarning, 5 }, + { DrawWarning, 6 }, + { FileOpenWarning, 7 }, + { FilterWarning, 8 }, + { ImageWarning, 9 }, + { MissingDelegateWarning, 10 }, + { ModuleWarning, 11 }, + { MonitorWarning, 12 }, + { OptionWarning, 13 }, + { PolicyWarning, 14 }, + { RandomWarning, 15 }, + { RegistryWarning, 16 }, + { ResourceLimitWarning, 17 }, + { StreamWarning, 18 }, + { TypeWarning, 19 }, + { WandWarning, 20 } + }; + size_t i; + + *kind = DIMS_EXC_KIND_COUNT - 1; + *severity = 1; + + /* Each kind occupies three consecutive values: warning, error, and fatal + * error. WandWarning has no fatal member, so it holds two. */ + for (i = 0; i < sizeof(table) / sizeof(table[0]); i++) { + int offset = exception_type - table[i].warning; + + if (offset >= 0 && offset <= 2) { + *kind = table[i].kind; + *severity = offset; + return; + } + } +} + +const char * +dims_metrics_curl_code_name(int index) +{ + return (index < 0 || index >= DIMS_CURL_CODE_COUNT) ? "" + : curl_code_name[index]; +} + +const char * +dims_metrics_operation_name(int index) +{ + return (index < 0 || index >= DIMS_OP_COUNT) ? "" : operation_name[index]; +} + +const char * +dims_metrics_exception_kind_name(int index) +{ + return (index < 0 || index >= DIMS_EXC_KIND_COUNT) ? "" + : exception_kind_name[index]; +} + +const char * +dims_metrics_exception_severity_name(int index) +{ + return (index < 0 || index >= DIMS_EXC_SEVERITY_COUNT) ? "" + : exception_severity_name[index]; +} + +const char * +dims_metrics_fetch_result_name(int index) +{ + return (index < 0 || index >= DIMS_FETCH_RESULT_COUNT) ? "" + : fetch_result_name[index]; +} + +const char * +dims_metrics_net_reason_name(int index) +{ + return (index < 0 || index >= DIMS_NET_REASON_COUNT) ? "" + : net_reason_name[index]; +} + +const char * +dims_metrics_sig_result_name(int index) +{ + return (index < 0 || index >= DIMS_SIG_RESULT_COUNT) ? "" + : sig_result_name[index]; +} + +void +dims_metrics_signature(int endpoint, dims_sig_result result) +{ + if (dims_metrics == NULL || endpoint < 0 || + endpoint >= DIMS_ENDPOINT_COUNT) { + return; + } + + apr_atomic_inc64(&dims_metrics->signature[endpoint][result]); +} + +void +dims_metrics_eurl(int ok) +{ + if (dims_metrics != NULL) { + apr_atomic_inc64(&dims_metrics->eurl[ok ? 0 : 1]); + } +} + +void +dims_metrics_netguard(int reason) +{ + /* DIMS_NET_OK is zero and names no refusal. */ + if (dims_metrics == NULL || reason < 1 || + reason > DIMS_NET_REASON_COUNT) { + return; + } + + apr_atomic_inc64(&dims_metrics->netguard[reason - 1]); +} + +void +dims_metrics_allowlist(int mode, int allowed) +{ + if (dims_metrics == NULL || mode < 0 || mode > 2) { + return; + } + + apr_atomic_inc64(&dims_metrics->allowlist[mode][allowed ? 0 : 1]); +} + +void +dims_metrics_operation(int op_index, int from_default, apr_time_t began, + int failed) +{ + dims_metrics_rec *m = dims_metrics; + + if (m == NULL || op_index < 0 || op_index >= DIMS_OP_COUNT) { + return; + } + + apr_atomic_inc64(&m->operations[op_index][from_default ? 1 : 0]); + + if (failed) { + apr_atomic_inc64(&m->operation_failures[op_index]); + } + + dims_metrics_observe(&m->operation_duration[op_index], + &dims_duration_buckets, (apr_uint64_t) (apr_time_now() - began)); +} + +void +dims_metrics_exception(int exception_type) +{ + int kind; + int severity; + + if (dims_metrics == NULL || exception_type == UndefinedException) { + return; + } + + dims_metrics_exception_slot(exception_type, &kind, &severity); + apr_atomic_inc64(&dims_metrics->exceptions[kind][severity]); +} + +void +dims_metrics_overlay_lookup(int result) +{ + if (dims_metrics != NULL && result >= 0 && result < 3) { + apr_atomic_inc64(&dims_metrics->overlay_lookups[result]); + } +} + +void +dims_metrics_overlay_eviction(void) +{ + if (dims_metrics != NULL) { + apr_atomic_inc64(&dims_metrics->overlay_evictions); + } +} + +void +dims_metrics_fetch(dims_fetch_result result, int curl_code) +{ + if (dims_metrics == NULL) { + return; + } + + apr_atomic_inc64(&dims_metrics->fetch_results[result]); + + if (result == DIMS_FETCH_TIMEOUT || result == DIMS_FETCH_TRANSPORT_ERROR || + result == DIMS_FETCH_REFUSED) { + apr_atomic_inc64(&dims_metrics->fetch_errors[ + dims_metrics_curl_code_index(curl_code)]); + } +} + +void +dims_metrics_error_image(int source, int failed) +{ + if (dims_metrics == NULL || source < 0 || source > 2) { + return; + } + + apr_atomic_inc64(&dims_metrics->error_images[source]); + + if (failed) { + apr_atomic_inc64(&dims_metrics->error_image_failures); + } +} diff --git a/src/metrics.h b/src/metrics.h new file mode 100644 index 0000000..f63a5a1 --- /dev/null +++ b/src/metrics.h @@ -0,0 +1,236 @@ +/* + * The metrics block, shared by every worker. + * + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#ifndef _DIMS_METRICS_H +#define _DIMS_METRICS_H + +#include "mod_dims.h" + +/* The endpoint a request arrived on. */ +typedef enum { + DIMS_ENDPOINT_DIMS3 = 0, + DIMS_ENDPOINT_DIMS4, + DIMS_ENDPOINT_DIMS5, + DIMS_ENDPOINT_LOCAL, + DIMS_ENDPOINT_COUNT +} dims_endpoint_t; + +/* One slot per dims_status_t, without DIMS_IGNORE. */ +#define DIMS_OUTCOME_COUNT 10 + +/* + * Response and origin status codes are reported by name from a list, because + * DimsOriginStatusMode forward copies whatever the origin returned. The last + * slot of each holds every code outside its list. + */ +#define DIMS_CODE_COUNT 11 +#define DIMS_ORIGIN_CODE_COUNT 13 + +/* Image formats reported by name. The last slot holds every other format. */ +#define DIMS_FORMAT_COUNT 9 + +/* Why a source fetch ended. */ +#define DIMS_FETCH_RESULT_COUNT 5 + +/* libcurl error codes reported by name. The last slot holds every other one. */ +#define DIMS_CURL_CODE_COUNT 9 + +/* dims_net_result without DIMS_NET_OK. */ +#define DIMS_NET_REASON_COUNT 6 + +/* How a signature check ended. */ +#define DIMS_SIG_RESULT_COUNT 6 + +/* The seventeen operations in the ops hash. */ +#define DIMS_OP_COUNT 17 + +/* ImageMagick exception kinds, and the three severities. */ +#define DIMS_EXC_KIND_COUNT 22 +#define DIMS_EXC_SEVERITY_COUNT 3 + +/* The widest bucket table below, plus the +Inf bucket. */ +#define DIMS_BUCKET_MAX 13 + +typedef struct { + apr_uint64_t bucket[DIMS_BUCKET_MAX]; + apr_uint64_t sum; + apr_uint64_t count; +} dims_histogram_rec; + +/* + * A bucket table. bound holds the finite upper bounds in ascending order, and + * the table has bounds + 1 buckets, because the last one is +Inf. + */ +typedef struct { + const double *bound; + int bounds; +} dims_bucket_spec; + +extern const dims_bucket_spec dims_duration_buckets; +extern const dims_bucket_spec dims_byte_buckets; +extern const dims_bucket_spec dims_frame_buckets; + +/* One per child. A child writes only the slot it claimed. */ +typedef struct { + apr_uint64_t pid; + apr_uint64_t resident_bytes; + apr_uint64_t virtual_bytes; + apr_uint64_t imagemagick_resource[4]; +} dims_process_rec; + +typedef struct { + apr_uint64_t requests[DIMS_ENDPOINT_COUNT][DIMS_OUTCOME_COUNT]; + apr_uint64_t responses[DIMS_ENDPOINT_COUNT][DIMS_CODE_COUNT]; + apr_uint64_t in_flight[DIMS_ENDPOINT_COUNT]; + apr_uint64_t origin_responses[DIMS_ORIGIN_CODE_COUNT]; + apr_uint64_t source_format[DIMS_FORMAT_COUNT]; + apr_uint64_t output_format[DIMS_FORMAT_COUNT]; + apr_uint64_t source_bytes_total; + apr_uint64_t output_bytes_total; + + apr_uint64_t fetch_results[DIMS_FETCH_RESULT_COUNT]; + apr_uint64_t fetch_errors[DIMS_CURL_CODE_COUNT]; + apr_uint64_t netguard[DIMS_NET_REASON_COUNT]; + apr_uint64_t allowlist[3][2]; + apr_uint64_t signature[DIMS_ENDPOINT_COUNT][DIMS_SIG_RESULT_COUNT]; + apr_uint64_t eurl[2]; + apr_uint64_t operations[DIMS_OP_COUNT][2]; + apr_uint64_t operation_failures[DIMS_OP_COUNT]; + apr_uint64_t exceptions[DIMS_EXC_KIND_COUNT][DIMS_EXC_SEVERITY_COUNT]; + apr_uint64_t overlay_lookups[3]; + apr_uint64_t overlay_evictions; + apr_uint64_t error_images[3]; + apr_uint64_t error_image_failures; + + dims_histogram_rec request_duration[DIMS_ENDPOINT_COUNT]; + dims_histogram_rec download_duration; + dims_histogram_rec imagemagick_duration; + dims_histogram_rec source_bytes; + dims_histogram_rec output_bytes; + dims_histogram_rec source_frames; + dims_histogram_rec operation_duration[DIMS_OP_COUNT]; + + /* The slot count comes from AP_MPMQ_HARD_LIMIT_DAEMONS. */ + apr_uint32_t process_slots; + dims_process_rec process[]; +} dims_metrics_rec; + +extern dims_metrics_rec *dims_metrics; + +/* Creates the block. Runs from dims_init, after apr_atomic_init. */ +apr_status_t dims_metrics_init(apr_pool_t *p, server_rec *s); + +/* Claims a process slot. Runs from dims_child_init. */ +void dims_metrics_child_init(void); + +/* The slot this child claimed, or NULL before it claimed one. */ +dims_process_rec *dims_metrics_process(void); + +/* + * Index lookups. Each returns a slot in the matching table, and the last slot + * for a value outside the list. + */ +int dims_metrics_outcome_index(int status); +int dims_metrics_code_index(int code); +int dims_metrics_origin_code_index(int code); +int dims_metrics_format_index(const char *format); +int dims_metrics_curl_code_index(int code); +int dims_metrics_operation_index(const char *operation); +void dims_metrics_exception_slot(int exception_type, int *kind, int *severity); + +/* The names the exposition writer prints for each index. */ +const char *dims_metrics_endpoint_name(int index); +const char *dims_metrics_outcome_name(int index); +const char *dims_metrics_code_name(int index); +const char *dims_metrics_origin_code_name(int index); +const char *dims_metrics_format_name(int index); +const char *dims_metrics_curl_code_name(int index); +const char *dims_metrics_operation_name(int index); +const char *dims_metrics_exception_kind_name(int index); +const char *dims_metrics_exception_severity_name(int index); +const char *dims_metrics_fetch_result_name(int index); +const char *dims_metrics_net_reason_name(int index); +const char *dims_metrics_sig_result_name(int index); + +/* The bucket a value belongs in, counting the +Inf bucket as spec->bounds. */ +int dims_metrics_bucket_index(const dims_bucket_spec *spec, double value); + +/* Adds one observation. value is microseconds, bytes, or frames. */ +void dims_metrics_observe(dims_histogram_rec *h, const dims_bucket_spec *spec, + apr_uint64_t value); + +/* Why a source fetch ended, as a slot in the fetch table. */ +typedef enum { + DIMS_FETCH_OK = 0, + DIMS_FETCH_TIMEOUT, + DIMS_FETCH_TRANSPORT_ERROR, + DIMS_FETCH_REFUSED, + DIMS_FETCH_HTTP_ERROR +} dims_fetch_result; + +/* Counts one source fetch. curl_code counts too when the result is an error. */ +void dims_metrics_fetch(dims_fetch_result result, int curl_code); + +/* How a signature check ended, as a slot in the signature table. */ +typedef enum { + DIMS_SIG_OK = 0, + DIMS_SIG_MISMATCH, + DIMS_SIG_EXPIRED, + DIMS_SIG_TOO_FAR_FUTURE, + DIMS_SIG_MISSING_KEY, + DIMS_SIG_BAD_CLIENT +} dims_sig_result; + +/* Counts one signature check. */ +void dims_metrics_signature(int endpoint, dims_sig_result result); + +/* Counts one eurl decryption. ok is nonzero when it succeeded. */ +void dims_metrics_eurl(int ok); + +/* Counts one network guard result, from a dims_net_result. */ +void dims_metrics_netguard(int reason); + +/* Counts one allowlist check under a dims_allowlist_mode. */ +void dims_metrics_allowlist(int mode, int allowed); + +/* Counts one operation call and its duration. */ +void dims_metrics_operation(int op_index, int from_default, apr_time_t began, + int failed); + +/* Counts one ImageMagick exception, from an ExceptionType. */ +void dims_metrics_exception(int exception_type); + +/* Counts one overlay cache lookup. result is a slot: hit, miss, expired. */ +void dims_metrics_overlay_lookup(int result); + +/* + * Counts one error image. source is 0 for a drawn image, 1 for a fetched one, + * and 2 for a server with neither. failed is nonzero when the error image + * itself failed. + */ +void dims_metrics_error_image(int source, int failed); + +/* Counts one overlay cache eviction. */ +void dims_metrics_overlay_eviction(void); + +/* + * Counts a request and records its duration when it ends. Registers a pool + * cleanup, so every return path in the handler reaches it exactly once. + */ +void dims_metrics_request_begin(dims_request_rec *d); + +/* + * Writes this child ImageMagick resource use and process memory into its slot. + * Runs at the end of a request, so a scrape reports what the last request + * left. + */ +void dims_metrics_sample_process(void); + +/* Answers a location that sets the dims-metrics handler. */ +apr_status_t dims_metrics_handler(request_rec *r); + +#endif diff --git a/src/metrics_report.c b/src/metrics_report.c new file mode 100644 index 0000000..1528116 --- /dev/null +++ b/src/metrics_report.c @@ -0,0 +1,598 @@ +/* + * The metrics endpoint. + * + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "metrics.h" +#include "module.h" + +#include +#include + +#include + +#include + +#include + +/* + * The exposition writer. + * + * Prometheus text 0.0.4. A family prints a # HELP line, a # TYPE line, and one + * line per series. A histogram prints a cumulative _bucket line per bound, + * then _sum and _count. + */ + +static apr_uint64_t +read64(const apr_uint64_t *value) +{ + return apr_atomic_read64((apr_uint64_t *) value); +} + +/* + * A label value with the three characters the format reserves escaped: a + * backslash, a double quote, and a newline. Every label the module writes is + * its own, apart from the library versions, which come from ImageMagick and + * libcurl. + */ +static const char * +escape(apr_pool_t *pool, const char *value) +{ + apr_size_t len; + char *out; + apr_size_t w = 0; + apr_size_t i; + + if (value == NULL) { + return ""; + } + + len = strlen(value); + out = apr_palloc(pool, len * 2 + 1); + + for (i = 0; i < len; i++) { + switch (value[i]) { + case '\\': out[w++] = '\\'; out[w++] = '\\'; break; + case '"': out[w++] = '\\'; out[w++] = '"'; break; + case '\n': out[w++] = '\\'; out[w++] = 'n'; break; + default: out[w++] = value[i]; break; + } + } + + out[w] = '\0'; + + return out; +} + +static void +head(request_rec *r, const char *name, const char *help, const char *type) +{ + ap_rprintf(r, "# HELP %s %s\n# TYPE %s %s\n", name, help, name, type); +} + +/* + * labels is the label set without braces, such as endpoint="dims3". Pass an + * empty string for a family with no labels. + */ +static void +histogram(request_rec *r, const char *name, const dims_histogram_rec *h, + const dims_bucket_spec *spec, int seconds, const char *labels) +{ + apr_uint64_t running = 0; + char braced[96]; + char bound[32]; + int i; + + for (i = 0; i < spec->bounds; i++) { + running += read64(&h->bucket[i]); + /* snprintf, because the httpd formatter prints .005 for 0.005 and + * rounds 1048576 to 1048580. A dashboard matches le as a string. */ + snprintf(bound, sizeof(bound), "%.15g", spec->bound[i]); + ap_rprintf(r, "%s_bucket{%s%sle=\"%s\"} %" APR_UINT64_T_FMT "\n", + name, labels, labels[0] ? "," : "", bound, running); + } + + running += read64(&h->bucket[spec->bounds]); + ap_rprintf(r, "%s_bucket{%s%sle=\"+Inf\"} %" APR_UINT64_T_FMT "\n", + name, labels, labels[0] ? "," : "", running); + + /* A family with no labels prints no braces. */ + if (labels[0] != '\0') { + apr_snprintf(braced, sizeof(braced), "{%s}", labels); + } else { + braced[0] = '\0'; + } + + if (seconds) { + ap_rprintf(r, "%s_sum%s %.6f\n", name, braced, + (double) read64(&h->sum) / 1000000.0); + } else { + ap_rprintf(r, "%s_sum%s %" APR_UINT64_T_FMT "\n", name, braced, + read64(&h->sum)); + } + + ap_rprintf(r, "%s_count%s %" APR_UINT64_T_FMT "\n", name, braced, + read64(&h->count)); +} + +/* + * The per process gauges. Each child writes its own slot at the end of a + * request, so the endpoint sums the live slots and reports the widest one. + */ +static void +write_process(request_rec *r, const dims_metrics_rec *m) +{ + static const char *const resource[4] = { "area", "memory", "map", "disk" }; + apr_uint64_t sum[4] = { 0, 0, 0, 0 }; + apr_uint64_t max[4] = { 0, 0, 0, 0 }; + apr_uint64_t resident_sum = 0, resident_max = 0; + apr_uint64_t virtual_sum = 0, virtual_max = 0; + apr_uint32_t live = 0; + apr_uint32_t i; + int k; + + for (i = 0; i < m->process_slots; i++) { + const dims_process_rec *slot = &m->process[i]; + apr_uint64_t resident; + apr_uint64_t virt; + + if (read64(&slot->pid) == 0) { + continue; + } + + live++; + + for (k = 0; k < 4; k++) { + apr_uint64_t value = read64(&slot->imagemagick_resource[k]); + + sum[k] += value; + if (value > max[k]) { + max[k] = value; + } + } + + resident = read64(&slot->resident_bytes); + resident_sum += resident; + if (resident > resident_max) { + resident_max = resident; + } + + virt = read64(&slot->virtual_bytes); + virtual_sum += virt; + if (virt > virtual_max) { + virtual_max = virt; + } + } + + head(r, "dims_imagemagick_resource_bytes", + "ImageMagick resource use, summed across the workers.", "gauge"); + for (k = 0; k < 4; k++) { + ap_rprintf(r, "dims_imagemagick_resource_bytes{resource=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", resource[k], sum[k]); + } + + head(r, "dims_imagemagick_resource_max_bytes", + "ImageMagick resource use by the widest worker.", "gauge"); + for (k = 0; k < 4; k++) { + ap_rprintf(r, "dims_imagemagick_resource_max_bytes{resource=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", resource[k], max[k]); + } + + /* The ceiling a worker runs under, from the same process the scrape + * reached. dims_child_init sets the same value in every worker. */ + head(r, "dims_imagemagick_resource_limit_bytes", + "The DimsImagemagick limit a worker runs under.", "gauge"); + ap_rprintf(r, "dims_imagemagick_resource_limit_bytes{resource=\"area\"} " + "%" APR_UINT64_T_FMT "\n", + (apr_uint64_t) MagickGetResourceLimit(AreaResource)); + ap_rprintf(r, "dims_imagemagick_resource_limit_bytes{resource=\"memory\"} " + "%" APR_UINT64_T_FMT "\n", + (apr_uint64_t) MagickGetResourceLimit(MemoryResource)); + ap_rprintf(r, "dims_imagemagick_resource_limit_bytes{resource=\"map\"} " + "%" APR_UINT64_T_FMT "\n", + (apr_uint64_t) MagickGetResourceLimit(MapResource)); + ap_rprintf(r, "dims_imagemagick_resource_limit_bytes{resource=\"disk\"} " + "%" APR_UINT64_T_FMT "\n", + (apr_uint64_t) MagickGetResourceLimit(DiskResource)); + + head(r, "dims_workers", "Worker processes holding a metrics slot.", + "gauge"); + ap_rprintf(r, "dims_workers %" APR_UINT64_T_FMT "\n", (apr_uint64_t) live); + + /* /proc/self/statm is Linux only, so a platform without it reports no + * memory rather than zero. */ + if (resident_sum > 0 || virtual_sum > 0) { + head(r, "dims_process_resident_bytes", + "Resident memory, summed across the workers.", "gauge"); + ap_rprintf(r, "dims_process_resident_bytes %" APR_UINT64_T_FMT "\n", + resident_sum); + + head(r, "dims_process_resident_max_bytes", + "Resident memory of the widest worker.", "gauge"); + ap_rprintf(r, "dims_process_resident_max_bytes %" APR_UINT64_T_FMT "\n", + resident_max); + + head(r, "dims_process_virtual_bytes", + "Virtual memory, summed across the workers.", "gauge"); + ap_rprintf(r, "dims_process_virtual_bytes %" APR_UINT64_T_FMT "\n", + virtual_sum); + } +} + +/* + * The httpd worker pool, read from the scoreboard rather than the metrics + * block. The scoreboard is the server's own record, so a scrape reports what + * every worker is doing now. + */ +static void +write_httpd(request_rec *r) +{ + static const char *const state_name[SERVER_NUM_STATUS] = { + "dead", "starting", "ready", "busy_read", "busy_write", + "busy_keepalive", "busy_log", "busy_dns", "closing", "graceful", + "idle_kill" + }; + apr_uint64_t state[SERVER_NUM_STATUS]; + apr_uint64_t connections = 0, write_completion = 0, lingering = 0; + apr_uint64_t keep_alive = 0, suspended = 0; + int daemons = 0, threads = 0, generation = 0; + int processes = 0; + int i, j; + + memset(state, 0, sizeof(state)); + + ap_mpm_query(AP_MPMQ_MAX_DAEMONS, &daemons); + ap_mpm_query(AP_MPMQ_MAX_THREADS, &threads); + ap_mpm_query(AP_MPMQ_GENERATION, &generation); + + if (threads < 1) { + threads = 1; + } + + if (ap_exists_scoreboard_image()) { + for (i = 0; i < daemons; i++) { + process_score *ps = ap_get_scoreboard_process(i); + + if (ps->pid != 0 && !ps->quiescing) { + processes++; + connections += ps->connections; + write_completion += ps->write_completion; + lingering += ps->lingering_close; + keep_alive += ps->keep_alive; + suspended += ps->suspended; + } + + for (j = 0; j < threads; j++) { + worker_score *ws = ap_get_scoreboard_worker_from_indexes(i, j); + + if (ws != NULL && ws->status < SERVER_NUM_STATUS) { + state[ws->status]++; + } + } + } + } + + head(r, "dims_httpd_workers", "Worker threads by scoreboard state.", + "gauge"); + for (i = 0; i < SERVER_NUM_STATUS; i++) { + ap_rprintf(r, "dims_httpd_workers{state=\"%s\"} %" APR_UINT64_T_FMT "\n", + state_name[i], state[i]); + } + + head(r, "dims_httpd_processes", "Child processes serving requests.", + "gauge"); + ap_rprintf(r, "dims_httpd_processes %d\n", processes); + + head(r, "dims_httpd_processes_limit", "The daemon ceiling the MPM runs under.", + "gauge"); + ap_rprintf(r, "dims_httpd_processes_limit %d\n", daemons); + + head(r, "dims_httpd_threads_per_process", "Threads in one child.", "gauge"); + ap_rprintf(r, "dims_httpd_threads_per_process %d\n", threads); + + head(r, "dims_httpd_connections", "Connections by state.", "gauge"); + ap_rprintf(r, "dims_httpd_connections{state=\"total\"} " + "%" APR_UINT64_T_FMT "\n", connections); + ap_rprintf(r, "dims_httpd_connections{state=\"write_completion\"} " + "%" APR_UINT64_T_FMT "\n", write_completion); + ap_rprintf(r, "dims_httpd_connections{state=\"lingering_close\"} " + "%" APR_UINT64_T_FMT "\n", lingering); + ap_rprintf(r, "dims_httpd_connections{state=\"keep_alive\"} " + "%" APR_UINT64_T_FMT "\n", keep_alive); + ap_rprintf(r, "dims_httpd_connections{state=\"suspended\"} " + "%" APR_UINT64_T_FMT "\n", suspended); + + /* A restart increments this, so a dashboard sees the reload. */ + head(r, "dims_httpd_generation", "The MPM generation.", "gauge"); + ap_rprintf(r, "dims_httpd_generation %d\n", generation); +} + +/* + * The build and the start time. + * + * dims_build_info names every library version, so DimsStatusVerbose off drops + * it the same way it drops the version lines from /dims-status/. + */ +static void +write_build(request_rec *r, const dims_config_rec *config) +{ + head(r, "dims_start_time_seconds", + "When the server last started, in seconds since the epoch.", + "gauge"); + ap_rprintf(r, "dims_start_time_seconds %" APR_TIME_T_FMT "\n", + apr_time_sec(ap_scoreboard_image->global->restart_time)); + + if (config == NULL || !config->status_verbose) { + return; + } + + head(r, "dims_build_info", "The running build, always 1.", "gauge"); + ap_rprintf(r, "dims_build_info{version=\"%s\",commit=\"%s\"," + "imagemagick=\"%s\",libcurl=\"%s\"} 1\n", + escape(r->pool, DIMS_VERSION), escape(r->pool, DIMS_COMMIT), + escape(r->pool, GetMagickVersion(NULL)), + escape(r->pool, curl_version())); +} + +/* The security, operation, and cache families. */ +static void +write_detail(request_rec *r, const dims_metrics_rec *m) +{ + static const char *const mode_name[3] = { "skip", "log", "enforce" }; + static const char *const overlay_name[3] = { "hit", "miss", "expired" }; + static const char *const error_source[3] = { "drawn", "fetched", "none" }; + char labels[96]; + int i, j; + + head(r, "dims_source_fetch_total", "Source fetches by result.", "counter"); + for (i = 0; i < DIMS_FETCH_RESULT_COUNT; i++) { + ap_rprintf(r, "dims_source_fetch_total{result=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_fetch_result_name(i), read64(&m->fetch_results[i])); + } + + head(r, "dims_source_fetch_errors_total", + "Source fetch failures by libcurl code.", "counter"); + for (i = 0; i < DIMS_CURL_CODE_COUNT; i++) { + ap_rprintf(r, "dims_source_fetch_errors_total{code=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_curl_code_name(i), read64(&m->fetch_errors[i])); + } + + head(r, "dims_netguard_refusals_total", + "Fetches the network guard refused, by reason.", "counter"); + for (i = 0; i < DIMS_NET_REASON_COUNT; i++) { + ap_rprintf(r, "dims_netguard_refusals_total{reason=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_net_reason_name(i), read64(&m->netguard[i])); + } + + head(r, "dims_allowlist_checks_total", + "Allowlist checks by mode and result.", "counter"); + for (i = 0; i < 3; i++) { + ap_rprintf(r, "dims_allowlist_checks_total{mode=\"%s\"," + "result=\"allowed\"} %" APR_UINT64_T_FMT "\n", + mode_name[i], read64(&m->allowlist[i][0])); + ap_rprintf(r, "dims_allowlist_checks_total{mode=\"%s\"," + "result=\"refused\"} %" APR_UINT64_T_FMT "\n", + mode_name[i], read64(&m->allowlist[i][1])); + } + + head(r, "dims_signature_checks_total", + "Signature checks by endpoint and result.", "counter"); + for (i = 0; i < DIMS_ENDPOINT_COUNT; i++) { + for (j = 0; j < DIMS_SIG_RESULT_COUNT; j++) { + ap_rprintf(r, "dims_signature_checks_total{endpoint=\"%s\"," + "result=\"%s\"} %" APR_UINT64_T_FMT "\n", + dims_metrics_endpoint_name(i), + dims_metrics_sig_result_name(j), + read64(&m->signature[i][j])); + } + } + + head(r, "dims_eurl_decrypt_total", "eurl decryptions by result.", + "counter"); + ap_rprintf(r, "dims_eurl_decrypt_total{result=\"ok\"} " + "%" APR_UINT64_T_FMT "\n", read64(&m->eurl[0])); + ap_rprintf(r, "dims_eurl_decrypt_total{result=\"failed\"} " + "%" APR_UINT64_T_FMT "\n", read64(&m->eurl[1])); + + /* One call, not one request. A multi-frame source runs the command loop + * once per frame, and strip and format also run without a command. */ + head(r, "dims_operations_total", "Operation functions called.", "counter"); + for (i = 0; i < DIMS_OP_COUNT; i++) { + ap_rprintf(r, "dims_operations_total{operation=\"%s\"," + "trigger=\"request\"} %" APR_UINT64_T_FMT "\n", + dims_metrics_operation_name(i), read64(&m->operations[i][0])); + ap_rprintf(r, "dims_operations_total{operation=\"%s\"," + "trigger=\"default\"} %" APR_UINT64_T_FMT "\n", + dims_metrics_operation_name(i), read64(&m->operations[i][1])); + } + + head(r, "dims_operation_failures_total", + "Operation functions that reported a failure.", "counter"); + for (i = 0; i < DIMS_OP_COUNT; i++) { + ap_rprintf(r, "dims_operation_failures_total{operation=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_operation_name(i), + read64(&m->operation_failures[i])); + } + + head(r, "dims_operation_duration_seconds", "Time in one operation call.", + "histogram"); + for (i = 0; i < DIMS_OP_COUNT; i++) { + apr_snprintf(labels, sizeof(labels), "operation=\"%s\"", + dims_metrics_operation_name(i)); + histogram(r, "dims_operation_duration_seconds", + &m->operation_duration[i], &dims_duration_buckets, 1, labels); + } + + head(r, "dims_imagemagick_exceptions_total", + "ImageMagick exceptions by kind and severity.", "counter"); + for (i = 0; i < DIMS_EXC_KIND_COUNT; i++) { + for (j = 0; j < DIMS_EXC_SEVERITY_COUNT; j++) { + ap_rprintf(r, "dims_imagemagick_exceptions_total{kind=\"%s\"," + "severity=\"%s\"} %" APR_UINT64_T_FMT "\n", + dims_metrics_exception_kind_name(i), + dims_metrics_exception_severity_name(j), + read64(&m->exceptions[i][j])); + } + } + + head(r, "dims_overlay_cache_lookups_total", + "Overlay cache lookups by result.", "counter"); + for (i = 0; i < 3; i++) { + ap_rprintf(r, "dims_overlay_cache_lookups_total{result=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + overlay_name[i], read64(&m->overlay_lookups[i])); + } + + head(r, "dims_overlay_cache_evictions_total", + "Overlays dropped to make room.", "counter"); + ap_rprintf(r, "dims_overlay_cache_evictions_total %" APR_UINT64_T_FMT "\n", + read64(&m->overlay_evictions)); + + head(r, "dims_error_images_total", "Error images sent, by source.", + "counter"); + for (i = 0; i < 3; i++) { + ap_rprintf(r, "dims_error_images_total{source=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + error_source[i], read64(&m->error_images[i])); + } + + head(r, "dims_error_image_failures_total", + "Failed requests whose error image also failed.", "counter"); + ap_rprintf(r, "dims_error_image_failures_total %" APR_UINT64_T_FMT "\n", + read64(&m->error_image_failures)); +} + +static void +write_metrics(request_rec *r, const dims_config_rec *config) +{ + dims_metrics_rec *m = dims_metrics; + char labels[64]; + int e, i; + + head(r, "dims_requests_total", "Requests by endpoint and outcome.", + "counter"); + for (e = 0; e < DIMS_ENDPOINT_COUNT; e++) { + for (i = 0; i < DIMS_OUTCOME_COUNT; i++) { + ap_rprintf(r, "dims_requests_total{endpoint=\"%s\",outcome=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_endpoint_name(e), dims_metrics_outcome_name(i), + read64(&m->requests[e][i])); + } + } + + head(r, "dims_responses_total", "Responses by endpoint and status code.", + "counter"); + for (e = 0; e < DIMS_ENDPOINT_COUNT; e++) { + for (i = 0; i < DIMS_CODE_COUNT; i++) { + ap_rprintf(r, "dims_responses_total{endpoint=\"%s\",code=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_endpoint_name(e), dims_metrics_code_name(i), + read64(&m->responses[e][i])); + } + } + + head(r, "dims_requests_in_flight", "Requests being served.", "gauge"); + for (e = 0; e < DIMS_ENDPOINT_COUNT; e++) { + ap_rprintf(r, "dims_requests_in_flight{endpoint=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_endpoint_name(e), read64(&m->in_flight[e])); + } + + head(r, "dims_origin_responses_total", + "Source fetches by the status the origin returned.", "counter"); + for (i = 0; i < DIMS_ORIGIN_CODE_COUNT; i++) { + ap_rprintf(r, "dims_origin_responses_total{code=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_origin_code_name(i), + read64(&m->origin_responses[i])); + } + + head(r, "dims_source_format_total", "Source images by format.", "counter"); + for (i = 0; i < DIMS_FORMAT_COUNT; i++) { + ap_rprintf(r, "dims_source_format_total{format=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_format_name(i), read64(&m->source_format[i])); + } + + head(r, "dims_output_format_total", "Responses by image format.", "counter"); + for (i = 0; i < DIMS_FORMAT_COUNT; i++) { + ap_rprintf(r, "dims_output_format_total{format=\"%s\"} " + "%" APR_UINT64_T_FMT "\n", + dims_metrics_format_name(i), read64(&m->output_format[i])); + } + + head(r, "dims_source_bytes_total", "Bytes fetched from an origin.", + "counter"); + ap_rprintf(r, "dims_source_bytes_total %" APR_UINT64_T_FMT "\n", + read64(&m->source_bytes_total)); + + head(r, "dims_output_bytes_total", "Bytes written to callers.", "counter"); + ap_rprintf(r, "dims_output_bytes_total %" APR_UINT64_T_FMT "\n", + read64(&m->output_bytes_total)); + + head(r, "dims_request_duration_seconds", "Time to serve a request.", + "histogram"); + for (e = 0; e < DIMS_ENDPOINT_COUNT; e++) { + apr_snprintf(labels, sizeof(labels), "endpoint=\"%s\"", + dims_metrics_endpoint_name(e)); + histogram(r, "dims_request_duration_seconds", &m->request_duration[e], + &dims_duration_buckets, 1, labels); + } + + head(r, "dims_source_fetch_duration_seconds", + "Time to fetch a source image.", "histogram"); + histogram(r, "dims_source_fetch_duration_seconds", &m->download_duration, + &dims_duration_buckets, 1, ""); + + head(r, "dims_imagemagick_duration_seconds", "Time inside ImageMagick.", + "histogram"); + histogram(r, "dims_imagemagick_duration_seconds", &m->imagemagick_duration, + &dims_duration_buckets, 1, ""); + + head(r, "dims_source_bytes", "Source image size.", "histogram"); + histogram(r, "dims_source_bytes", &m->source_bytes, &dims_byte_buckets, 0, + ""); + + head(r, "dims_output_bytes", "Response image size.", "histogram"); + histogram(r, "dims_output_bytes", &m->output_bytes, &dims_byte_buckets, 0, + ""); + + head(r, "dims_source_frames", "Frames in a source image.", "histogram"); + histogram(r, "dims_source_frames", &m->source_frames, &dims_frame_buckets, + 0, ""); + + write_detail(r, m); + write_process(r, m); + write_httpd(r); + write_build(r, config); +} + +apr_status_t +dims_metrics_handler(request_rec *r) +{ + dims_config_rec *config = (dims_config_rec *) ap_get_module_config( + r->server->module_config, &dims_module); + + if (config == NULL || !config->metrics_enabled || dims_metrics == NULL) { + return DECLINED; + } + + if (r->method_number != M_GET) { + return HTTP_METHOD_NOT_ALLOWED; + } + + ap_set_content_type(r, "text/plain; version=0.0.4; charset=utf-8"); + + if (!r->header_only) { + write_metrics(r, config); + ap_rflush(r); + } + + return OK; +} diff --git a/src/mod_dims.c b/src/mod_dims.c index 8ba090d..14c456a 100644 --- a/src/mod_dims.c +++ b/src/mod_dims.c @@ -29,6 +29,7 @@ #include "mod_dims.h" #include "curl.h" #include "netguard.h" +#include "metrics.h" #include "status.h" #include "pipeline.h" #include "svgguard.h" @@ -204,6 +205,8 @@ dims_fetch_remote_image(dims_request_rec *d, const char *url) d->status = DIMS_NETWORK_REFUSED; d->fetch_http_status = HTTP_BAD_REQUEST; + dims_metrics_fetch(DIMS_FETCH_REFUSED, 0); + return 1; } @@ -236,8 +239,22 @@ dims_fetch_remote_image(dims_request_rec *d, const char *url) if (d->net_refusal != DIMS_NET_OK) { d->status = DIMS_NETWORK_REFUSED; d->fetch_http_status = HTTP_BAD_REQUEST; + + /* The socket callback refused it, so the guard has not + * counted this one. */ + if (code != CURLE_TOO_MANY_REDIRECTS) { + dims_metrics_netguard(d->net_refusal); + } } + /* The libcurl code names what went wrong, where the outcome only + * says the fetch failed. */ + dims_metrics_fetch( + (d->net_refusal != DIMS_NET_OK) ? DIMS_FETCH_REFUSED + : (code == CURLE_OPERATION_TIMEDOUT) + ? DIMS_FETCH_TIMEOUT : DIMS_FETCH_TRANSPORT_ERROR, + code); + d->download_time = (apr_time_now() - start_time) / 1000; return 1; @@ -255,6 +272,8 @@ dims_fetch_remote_image(dims_request_rec *d, const char *url) d->status = DIMS_FILE_NOT_FOUND; } + dims_metrics_fetch(DIMS_FETCH_HTTP_ERROR, 0); + if(image_data.data) { free(image_data.data); } @@ -262,6 +281,8 @@ dims_fetch_remote_image(dims_request_rec *d, const char *url) return 1; } + dims_metrics_fetch(DIMS_FETCH_OK, 0); + /* ImageMagick's SVG renderer reads a local file named by an * href, so refuse a source that references an external resource before * the renderer sees it. */ @@ -316,6 +337,16 @@ dims_fetch_remote_image(dims_request_rec *d, const char *url) } d->imagemagick_time += (apr_time_now() - start_time) / 1000; + /* The format the wand read, kept as a metrics slot because the string + * belongs to ImageMagick. The error image reports its own format, so + * only a source fetch records one. */ + if (url != NULL) { + char *source_format = MagickGetImageFormat(d->wand); + + d->source_format_index = dims_metrics_format_index(source_format); + MagickRelinquishMemory(source_format); + } + if(d->status != DIMS_DOWNLOAD_TIMEOUT) { d->original_image_size = image_data.used; } @@ -492,6 +523,10 @@ dims_send_image(dims_request_rec *d) blob = MagickGetImagesBlob(d->wand, &length); d->imagemagick_time += (apr_time_now() - start_time) / 1000; + /* What the caller receives. The pool cleanup reports it. */ + d->output_format_index = dims_metrics_format_index(format); + d->output_bytes = (blob != NULL) ? (apr_uint64_t) length : 0; + /* Set the Content-Type based on the image format. */ content_type = apr_psprintf(d->pool, "image/%s", format); ap_content_type_tolower(content_type); @@ -547,19 +582,6 @@ dims_send_image(dims_request_rec *d) DestroyMagickWand(d->wand); d->wand = NULL; - /* After the image is sent record stats about this request. */ - if(d->status == DIMS_SUCCESS) { - apr_atomic_inc32(&stats->success_count); - } else { - apr_atomic_inc32(&stats->failure_count); - } - - if(d->status == DIMS_DOWNLOAD_TIMEOUT) { - apr_atomic_inc32(&stats->download_timeout_count); - } else if(d->status == DIMS_IMAGEMAGICK_TIMEOUT) { - apr_atomic_inc32(&stats->imagemagick_timeout_count); - } - /* Record metrics for logging. */ snprintf(buf, 128, "%d", d->status); apr_table_set(d->r->notes, "DIMS_STATUS", buf); @@ -600,6 +622,7 @@ dims_free_request(dims_request_rec *d) msg = MagickGetException(d->wand, &type); if (type != UndefinedException && msg) { + dims_metrics_exception(type); ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, d->r, "Imagemagick error, '%s', on request: %s ", msg, d->r->uri); } @@ -721,17 +744,23 @@ dims_cleanup(dims_request_rec *d, const char *err_msg, int status) if (dims_draw_error_image(d)) { dims_strip_error_image(d); + dims_metrics_error_image(0, 0); return dims_send_image(d); } + dims_metrics_error_image(0, 1); dims_free_request(d); } else if (d->no_image_url) { d->wand = NewMagickWand(); if (!dims_fetch_remote_image(d, NULL)) { dims_strip_error_image(d); + dims_metrics_error_image(1, 0); return dims_send_image(d); } + dims_metrics_error_image(1, 1); dims_free_request(d); + } else { + dims_metrics_error_image(2, 0); } /* With no error image to send, the status is all the caller gets. This is @@ -872,12 +901,21 @@ dims_run_commands(dims_request_rec *d, apr_hash_t *ops, int *exc_strip_cmd, func = apr_hash_get(ops, command, APR_HASH_KEY_STRING); if (func != NULL) { apr_status_t code; + apr_time_t began; ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "Executing command %s(%s), on request %s", command, args, d->r->uri); - if ((code = func(d, args, err)) != DIMS_SUCCESS) { + began = apr_time_now(); + code = func(d, args, err); + + /* One call, not one request. A multi-frame source runs this loop + * once per frame. */ + dims_metrics_operation(dims_metrics_operation_index(command), 0, + began, code != DIMS_SUCCESS); + + if (code != DIMS_SUCCESS) { return code; } } @@ -911,7 +949,6 @@ dims_process_image(dims_request_rec *d) if (rc != OK) { dims_set_cache_headers(d); dims_free_request(d); - apr_atomic_inc32(&stats->success_count); return rc; } } @@ -970,6 +1007,8 @@ dims_process_image(dims_request_rec *d) size_t images = MagickGetNumberImages(d->wand); bool should_flatten = false; + d->source_frames = (apr_uint64_t) images; + if (images > 1) { int i; for (i = 0; d->commands != NULL && i < d->commands->nelts; i++) { @@ -1047,8 +1086,15 @@ dims_process_image(dims_request_rec *d) if (use_default) { const char *err = NULL; apr_status_t code; + apr_time_t began = apr_time_now(); + + code = dims_format_operation(d, + d->config->default_output_format, &err); + + dims_metrics_operation(dims_metrics_operation_index("format"), + 1, began, code != DIMS_SUCCESS); - if((code = dims_format_operation(d, d->config->default_output_format, &err)) != DIMS_SUCCESS) { + if (code != DIMS_SUCCESS) { return dims_cleanup(d, err, code); } } @@ -1063,11 +1109,18 @@ dims_process_image(dims_request_rec *d) if(strip_func != NULL) { const char *err = NULL; apr_status_t code; + apr_time_t began; ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, d->r, "Executing default strip command, on request %s", d->r->uri); - if((code = strip_func(d, NULL, &err)) != DIMS_SUCCESS) { + began = apr_time_now(); + code = strip_func(d, NULL, &err); + + dims_metrics_operation(dims_metrics_operation_index("strip"), 1, + began, code != DIMS_SUCCESS); + + if (code != DIMS_SUCCESS) { return dims_cleanup(d, err, code); } } diff --git a/src/mod_dims.h b/src/mod_dims.h index d5651ac..cd81c4b 100644 --- a/src/mod_dims.h +++ b/src/mod_dims.h @@ -182,6 +182,9 @@ struct dims_config_rec { * DimsStatusVerbose. */ int status_verbose; + /* Whether the module serves /metrics. Set from DimsMetricsEnabled. */ + int metrics_enabled; + /* Bounds on the overlay cache. Zero turns either off. Set from * DimsOverlayCacheMaxEntries and DimsOverlayCacheMaxAge. */ int overlay_cache_max_entries; @@ -234,6 +237,17 @@ struct dims_request_rec { char *image_url; int use_no_image; + /* Which endpoint served this, as a dims_endpoint_t. */ + int endpoint; + + /* Slots in the metrics format table, or -1 before the format is known. */ + int source_format_index; + int output_format_index; + + /* Bytes written to the caller, and frames in the source. */ + apr_uint64_t output_bytes; + apr_uint64_t source_frames; + /* The URL to the NOIMAGE image in case of failures. */ char *no_image_url; diff --git a/src/module.c b/src/module.c index b084348..b02ecea 100644 --- a/src/module.c +++ b/src/module.c @@ -18,6 +18,7 @@ #include "overlay_cache.h" #include "pipeline.h" #include "profile.h" +#include "metrics.h" #include "status.h" #include @@ -30,7 +31,6 @@ static int dims_init(apr_pool_t *p, apr_pool_t *plog, apr_pool_t* ptemp, server_rec *s) { apr_status_t status; - apr_size_t retsize; void *first_pass = NULL; /* @@ -93,42 +93,11 @@ dims_init(apr_pool_t *p, apr_pool_t *plog, apr_pool_t* ptemp, server_rec *s) if (status != APR_SUCCESS) return HTTP_INTERNAL_SERVER_ERROR; - /* Create shared memory block */ - status = apr_shm_create(&shm, sizeof(dims_stats_rec), NULL, p); + status = dims_metrics_init(p, s); if (status != APR_SUCCESS) { - ap_log_error(APLOG_MARK, APLOG_ERR, 0, s, - "mod_dims : Error creating shm block\n"); return status; } - /* Check size of shared memory block */ - retsize = apr_shm_size_get(shm); - if (retsize != sizeof(dims_stats_rec)) { - ap_log_error(APLOG_MARK, APLOG_ERR, 0, s, - "mod_dims : Error allocating shared memory block\n"); - return status; - } - - /* Init shm block */ - stats = apr_shm_baseaddr_get(shm); - if (stats == NULL) { - ap_log_error(APLOG_MARK, APLOG_ERR, 0, s, - "mod_dims : Error creating status block.\n"); - return status; - } - memset(stats, 0, retsize); - - if (retsize < sizeof(dims_stats_rec)) { - ap_log_error(APLOG_MARK, APLOG_NOTICE, 0, s, - "mod_dims : Not enough memory allocated!! Giving up"); - return HTTP_INTERNAL_SERVER_ERROR; - } - - stats->success_count = 1; - stats->failure_count = 0; - stats->download_timeout_count = 0; - stats->imagemagick_timeout_count = 0; - return OK; } @@ -161,6 +130,8 @@ dims_child_init(apr_pool_t *p, server_rec *s) MagickWandGenesis(); + dims_metrics_child_init(); + dims_profiles_load(p, s, config->profile_dir); /* Every limit is per process, so the total a host can use is this diff --git a/src/netguard.c b/src/netguard.c index e85d78b..2fee6ca 100644 --- a/src/netguard.c +++ b/src/netguard.c @@ -6,6 +6,7 @@ */ #include "netguard.h" +#include "metrics.h" #include #include @@ -230,8 +231,8 @@ dims_host_allowed(apr_table_t *whitelist, const char *hostname) return found; } -dims_net_result -dims_validate_image_url(dims_request_rec *d, const char *url, dims_allowlist_mode mode) +static dims_net_result +validate_url(dims_request_rec *d, const char *url, dims_allowlist_mode mode) { apr_uri_t uri; @@ -249,23 +250,41 @@ dims_validate_image_url(dims_request_rec *d, const char *url, dims_allowlist_mod return DIMS_NET_BAD_URL; } - if (mode != DIMS_ALLOWLIST_SKIP && - !dims_host_allowed(d->config->whitelist, uri.hostname)) { - if (mode == DIMS_ALLOWLIST_ENFORCE) { - return DIMS_NET_HOST_NOT_ALLOWED; - } + if (mode != DIMS_ALLOWLIST_SKIP) { + int allowed = dims_host_allowed(d->config->whitelist, uri.hostname); - /* Report what enforcing would cost, so an operator can fill the - * allowlist from the log before setting the directive. */ - ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, d->r, - "DimsAllowlistSigned enforce would refuse %s: %s, " - "on request: %s", uri.hostname, - dims_net_reason(DIMS_NET_HOST_NOT_ALLOWED), d->r->uri); + dims_metrics_allowlist(mode, allowed); + + if (!allowed) { + if (mode == DIMS_ALLOWLIST_ENFORCE) { + return DIMS_NET_HOST_NOT_ALLOWED; + } + + /* Report what enforcing would cost, so an operator can fill the + * allowlist from the log before setting the directive. */ + ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, d->r, + "DimsAllowlistSigned enforce would refuse %s: %s, " + "on request: %s", uri.hostname, + dims_net_reason(DIMS_NET_HOST_NOT_ALLOWED), + d->r->uri); + } } return DIMS_NET_OK; } +/* Records the result, so every refusal counts once whatever refused it. */ +dims_net_result +dims_validate_image_url(dims_request_rec *d, const char *url, + dims_allowlist_mode mode) +{ + dims_net_result result = validate_url(d, url, mode); + + dims_metrics_netguard(result); + + return result; +} + /* * Runs once per connection, after the name resolves and before the socket * opens. A name that resolves to a refused address is refused whatever it is diff --git a/src/overlay_cache.c b/src/overlay_cache.c index c80660d..ad2b851 100644 --- a/src/overlay_cache.c +++ b/src/overlay_cache.c @@ -6,6 +6,7 @@ */ #include "overlay_cache.h" +#include "metrics.h" #include #include @@ -196,6 +197,7 @@ dims_overlay_memcache_get(const char *url) { dims_overlay_memcache *cache = overlay_memcache; MagickWand *clone = NULL; + int expired = 0; int i; if (cache == NULL || url == NULL) { @@ -219,6 +221,7 @@ dims_overlay_memcache_get(const char *url) free(entry->url); entry->url = NULL; entry->wand = NULL; + expired = 1; break; } @@ -232,6 +235,10 @@ dims_overlay_memcache_get(const char *url) apr_thread_mutex_unlock(cache->mutex); + /* An entry past its age reports separately from a name the cache never + * held, because the two point at different settings. */ + dims_metrics_overlay_lookup(expired ? 2 : (clone != NULL) ? 0 : 1); + return clone; } @@ -283,9 +290,11 @@ dims_overlay_memcache_put(const char *url, MagickWand *wand) return; } + /* The slot held another overlay, so storing this one drops it. */ if (slot->url != NULL) { DestroyMagickWand(slot->wand); free(slot->url); + dims_metrics_overlay_eviction(); } slot->url = key; diff --git a/src/status.c b/src/status.c index 2a3b506..b6d0bbd 100644 --- a/src/status.c +++ b/src/status.c @@ -7,12 +7,45 @@ */ #include "status.h" +#include "metrics.h" #include "module.h" #include -dims_stats_rec *stats; -apr_shm_t *shm; +/* + * The four numbers this endpoint prints, summed from the metrics block. A + * request counts once, under the endpoint it arrived on. + */ +static apr_uint64_t +count_outcome(int outcome) +{ + apr_uint64_t total = 0; + int e; + + if (dims_metrics == NULL) { + return 0; + } + + for (e = 0; e < DIMS_ENDPOINT_COUNT; e++) { + total += apr_atomic_read64(&dims_metrics->requests[e][outcome]); + } + + return total; +} + +/* Every outcome apart from success. */ +static apr_uint64_t +count_failures(void) +{ + apr_uint64_t total = 0; + int i; + + for (i = 1; i < DIMS_OUTCOME_COUNT; i++) { + total += count_outcome(i); + } + + return total; +} static void show_time(request_rec *r, apr_interval_time_t tsecs) @@ -72,14 +105,14 @@ dims_status_handler(request_rec *r) ap_rprintf(r, "\nDetails\n-------\n"); - ap_rprintf(r, "Successful requests: %d\n", - apr_atomic_read32(&stats->success_count)); - ap_rprintf(r, "Failed requests: %d\n\n", - apr_atomic_read32(&stats->failure_count)); - ap_rprintf(r, "Download timeouts: %d\n", - apr_atomic_read32(&stats->download_timeout_count)); - ap_rprintf(r, "Imagemagick Timeouts: %d\n", - apr_atomic_read32(&stats->imagemagick_timeout_count)); + ap_rprintf(r, "Successful requests: %" APR_UINT64_T_FMT "\n", + count_outcome(DIMS_SUCCESS)); + ap_rprintf(r, "Failed requests: %" APR_UINT64_T_FMT "\n\n", + count_failures()); + ap_rprintf(r, "Download timeouts: %" APR_UINT64_T_FMT "\n", + count_outcome(DIMS_DOWNLOAD_TIMEOUT)); + ap_rprintf(r, "Imagemagick Timeouts: %" APR_UINT64_T_FMT "\n", + count_outcome(DIMS_IMAGEMAGICK_TIMEOUT)); ap_rflush(r); diff --git a/src/status.h b/src/status.h index 9a99c62..8c03065 100644 --- a/src/status.h +++ b/src/status.h @@ -11,21 +11,6 @@ #include "mod_dims.h" -/* - * Request counters, kept in shared memory so every worker adds to the same - * ones and the status endpoint reports a whole server rather than whichever - * worker answered. - */ -typedef struct { - apr_uint32_t success_count; - apr_uint32_t failure_count; - apr_uint32_t download_timeout_count; - apr_uint32_t imagemagick_timeout_count; -} dims_stats_rec; - -extern dims_stats_rec *stats; -extern apr_shm_t *shm; - /* Answers /dims-status/. */ apr_status_t dims_status_handler(request_rec *r); diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index aefdd11..fe6f9d7 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -22,6 +22,7 @@ add_executable(dims_test http/test_signing.c http/test_sources.c http/test_legacy_endpoints.c + http/test_metrics.c http/test_no_error_image.c http/test_source_limit.c http/test_status.c @@ -30,6 +31,7 @@ add_executable(dims_test http/test_watermark.c lib/common.c lib/golden.c + lib/prometheus.c lib/imagesize.c lib/request.c lib/signing.c @@ -103,6 +105,7 @@ add_executable(dims_unit_test unit/test_resize.c unit/test_rotate.c unit/test_encryption.c + unit/test_metrics.c unit/test_netguard.c unit/test_overlay_cache.c unit/test_param.c @@ -112,8 +115,10 @@ add_executable(dims_unit_test unit/test_thumbnail.c unit/test_watermark.c lib/golden.c + lib/prometheus.c lib/test.c ${CMAKE_SOURCE_DIR}/src/encryption.c + ${CMAKE_SOURCE_DIR}/src/metrics.c ${CMAKE_SOURCE_DIR}/src/netguard.c ${CMAKE_SOURCE_DIR}/src/overlay_cache.c ${CMAKE_SOURCE_DIR}/src/signature.c diff --git a/test/conf/dims-test.conf b/test/conf/dims-test.conf index b2af420..f4bc70c 100644 --- a/test/conf/dims-test.conf +++ b/test/conf/dims-test.conf @@ -39,6 +39,14 @@ DimsAddWhitelist origin SetHandler dims-status +# The metrics endpoint. The directive is the switch and the location names the +# path, so a case can turn it off by leaving the directive at its default. +DimsMetricsEnabled on + + + SetHandler dims-metrics + + # A location the server denies. A /dims3/ request that names a local file here # must not read it: the module honors the access check the subrequest runs. @@ -252,3 +260,18 @@ Listen 8008 SetHandler None + +Listen 8009 + +# A server that sets the metrics handler and turns the directive off, so the +# endpoint returns 404. A virtual host inherits the main server directives, so +# this one names it. + + ServerName metricsoff + + DimsMetricsEnabled off + + + SetHandler dims-metrics + + diff --git a/test/endurance/observe/README.md b/test/endurance/observe/README.md new file mode 100644 index 0000000..fa972cd --- /dev/null +++ b/test/endurance/observe/README.md @@ -0,0 +1,66 @@ +# Watching a soak + +Prometheus scrapes the soak server and Grafana draws it. + +``` +bash test/endurance/run.sh & +bash test/endurance/observe/up.sh +``` + +`up.sh` prints the dashboard address. Grafana listens on every interface at +port 3000, so another machine on the network reaches it. + +The soak creates `dims-soak-net` and gives its server the alias `dims`, so +this stack joins that network and scrapes `dims:8001`. Start the soak first. + +`run.sh` sets `DIMS_METRICS_ENABLED=on`, so a run publishes its metrics with +no further setting. + +## The dashboard + +Six sections, from the top. + +**Overview** reports the request rate, the two error ratios, the p99 latency, +requests in flight, and resident memory. + +The two ratios separate what the caller sent from what the module could not +serve. A 4xx is a bad signature, an unknown client, or an argument the module +cannot parse. A 5xx is the module or its source failing. A soak drives +malformed requests on purpose, so its 4xx line stays high and says nothing +about the module. + +**Request path** breaks the rate down by outcome, by status code, and by +endpoint, with the latency quantiles beside them. + +**Source fetch** separates a slow origin from a broken one. The libcurl code +panel tells DNS from TLS from a reset connection, and the origin status panel +reports what the origin returned. + +**Image processing** answers which command spends the time. The mean seconds +per call panel is the one that names an expensive operation, because a +watermark fetches an overlay and a resize does not. The exception panel splits +ImageMagick failures by kind: `resource_limit` is the pixel cache reaching a +ceiling, `corrupt_image` is a bad source, and `policy` is `policy.xml` +refusing a coder. + +**Guard and signature** reports what the network guard refused and why, the +allowlist checks by mode, and the signature results. Under +`DimsAllowlistSigned log` the refused line is what `enforce` would reject. + +**Resources** puts ImageMagick use beside its limit, so the ratio is visible. +The process memory panel is the one a soak watches for a trend. + +## Stopping it + +``` +docker compose -f test/endurance/observe/compose.yaml down +``` + +Prometheus keeps 24 hours and stores it in the container, so removing the +container drops the history. + +## Anonymous access + +Grafana runs with the login form off and anonymous viewing on. It reads a +local soak and holds nothing worth protecting. A deployment that reaches +further sets `GF_AUTH_ANONYMOUS_ENABLED=false` in `compose.yaml`. diff --git a/test/endurance/observe/compose.yaml b/test/endurance/observe/compose.yaml new file mode 100644 index 0000000..0e8c759 --- /dev/null +++ b/test/endurance/observe/compose.yaml @@ -0,0 +1,41 @@ +# Prometheus and Grafana for watching a soak run. +# +# bash test/endurance/observe/up.sh +# +# The soak creates dims-soak-net and gives its server the alias "dims", so +# Prometheus reaches it at dims:8001. Start the soak first. +name: dims-observe + +services: + prometheus: + image: prom/prometheus:v3.1.0 + command: + - --config.file=/etc/prometheus/prometheus.yml + - --storage.tsdb.retention.time=24h + volumes: + - ./prometheus.yml:/etc/prometheus/prometheus.yml:ro + networks: [soak] + restart: unless-stopped + + grafana: + image: grafana/grafana:11.5.1 + ports: + # Every interface, so the dashboard is reachable from another machine. + - "0.0.0.0:3000:3000" + environment: + GF_AUTH_ANONYMOUS_ENABLED: "true" + GF_AUTH_ANONYMOUS_ORG_ROLE: Viewer + GF_AUTH_DISABLE_LOGIN_FORM: "true" + GF_SECURITY_ALLOW_EMBEDDING: "true" + GF_USERS_DEFAULT_THEME: dark + volumes: + - ./grafana/datasources:/etc/grafana/provisioning/datasources:ro + - ./grafana/dashboards:/etc/grafana/provisioning/dashboards:ro + networks: [soak] + depends_on: [prometheus] + restart: unless-stopped + +networks: + soak: + name: dims-soak-net + external: true diff --git a/test/endurance/observe/grafana/dashboards/mod_dims.json b/test/endurance/observe/grafana/dashboards/mod_dims.json new file mode 100644 index 0000000..add1d44 --- /dev/null +++ b/test/endurance/observe/grafana/dashboards/mod_dims.json @@ -0,0 +1,1884 @@ +{ + "uid": "mod-dims-soak", + "title": "mod_dims", + "tags": [ + "mod_dims" + ], + "timezone": "browser", + "schemaVersion": 39, + "version": 1, + "refresh": "5s", + "time": { + "from": "now-15m", + "to": "now" + }, + "editable": true, + "graphTooltip": 1, + "panels": [ + { + "id": 101, + "title": "Overview", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 0, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 102, + "title": "Requests / sec", + "type": "stat", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "sum(rate(dims_requests_total[1m]))", + "legendFormat": "total", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 103, + "title": "Server error ratio", + "type": "stat", + "description": "Responses the module could not serve, as a share of all responses. A 4xx is the caller's request, so it counts in the panel beside this one.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 4, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "sum(rate(dims_responses_total{code=~\"5..\"}[1m])) / clamp_min(sum(rate(dims_responses_total[1m])), 0.001)", + "legendFormat": "5xx", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "percentunit", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 104, + "title": "p99 latency", + "type": "stat", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 8, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "histogram_quantile(0.99, sum by (le) (rate(dims_request_duration_seconds_bucket[1m])))", + "legendFormat": "p99", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 105, + "title": "In flight", + "type": "stat", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "sum(dims_requests_in_flight)", + "legendFormat": "in flight", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "short", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 106, + "title": "Resident memory", + "type": "stat", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 16, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "dims_process_resident_bytes", + "legendFormat": "resident", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "bytes", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 999, + "title": "Caller error ratio", + "type": "stat", + "description": "Requests the module refused as malformed: a bad signature, an unknown client, or an argument it cannot parse. The caller sent these, so they report apart from a server error.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 20, + "y": 1, + "w": 4, + "h": 5 + }, + "targets": [ + { + "expr": "sum(rate(dims_responses_total{code=~\"4..\"}[1m])) / clamp_min(sum(rate(dims_responses_total[1m])), 0.001)", + "legendFormat": "4xx", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "percentunit", + "custom": {}, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ], + "fields": "", + "values": false + }, + "colorMode": "value", + "graphMode": "area", + "textMode": "auto" + } + }, + { + "id": 108, + "title": "Request path", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 6, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 109, + "title": "Requests by outcome", + "type": "timeseries", + "description": "Every request counts once, under the endpoint it arrived on.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 7, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (outcome) (rate(dims_requests_total[1m]))", + "legendFormat": "{{outcome}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 110, + "title": "Responses by status", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 7, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (code) (rate(dims_responses_total[1m]))", + "legendFormat": "{{code}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 111, + "title": "Latency quantiles", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 15, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "histogram_quantile(0.50, sum by (le) (rate(dims_request_duration_seconds_bucket[1m])))", + "legendFormat": "p50", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "histogram_quantile(0.90, sum by (le) (rate(dims_request_duration_seconds_bucket[1m])))", + "legendFormat": "p90", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "histogram_quantile(0.99, sum by (le) (rate(dims_request_duration_seconds_bucket[1m])))", + "legendFormat": "p99", + "refId": "C", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 112, + "title": "Requests by endpoint", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 15, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (endpoint) (rate(dims_requests_total[1m]))", + "legendFormat": "{{endpoint}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 113, + "title": "Source fetch", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 23, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 114, + "title": "Fetch result", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 24, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (result) (rate(dims_source_fetch_total[1m]))", + "legendFormat": "{{result}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 115, + "title": "Fetch errors by libcurl code", + "type": "timeseries", + "description": "Separates DNS from TLS from a slow origin.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 8, + "y": 24, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (code) (rate(dims_source_fetch_errors_total[1m])) > 0", + "legendFormat": "{{code}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 116, + "title": "Origin status", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 16, + "y": 24, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (code) (rate(dims_origin_responses_total[1m])) > 0", + "legendFormat": "{{code}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 117, + "title": "Origin throughput", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 31, + "w": 12, + "h": 7 + }, + "targets": [ + { + "expr": "rate(dims_source_bytes_total[1m])", + "legendFormat": "source in", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "rate(dims_output_bytes_total[1m])", + "legendFormat": "output out", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "Bps", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 118, + "title": "Source format", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 31, + "w": 12, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (format) (rate(dims_source_format_total[1m])) > 0", + "legendFormat": "{{format}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 119, + "title": "Image processing", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 38, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 120, + "title": "Time by operation", + "type": "timeseries", + "description": "Which command spends the service's time.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 39, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "topk(8, sum by (operation) (rate(dims_operation_duration_seconds_sum[1m])))", + "legendFormat": "{{operation}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 121, + "title": "Mean seconds per operation call", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 39, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (operation) (rate(dims_operation_duration_seconds_sum[1m])) / clamp_min(sum by (operation) (rate(dims_operation_duration_seconds_count[1m])), 0.001) > 0", + "legendFormat": "{{operation}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 122, + "title": "Operation calls", + "type": "timeseries", + "description": "One call, not one request. A multi-frame source runs the loop per frame.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 47, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (operation) (rate(dims_operations_total[1m])) > 0", + "legendFormat": "{{operation}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "ops", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 123, + "title": "ImageMagick exceptions", + "type": "timeseries", + "description": "resource_limit is the pixel cache. corrupt_image is a bad source. policy is policy.xml.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 47, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "sum by (kind) (rate(dims_imagemagick_exceptions_total[1m])) > 0", + "legendFormat": "{{kind}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "ops", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 124, + "title": "Source frames", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 55, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "histogram_quantile(0.99, sum by (le) (rate(dims_source_frames_bucket[1m])))", + "legendFormat": "p99 frames", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "histogram_quantile(0.50, sum by (le) (rate(dims_source_frames_bucket[1m])))", + "legendFormat": "p50 frames", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "short", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 125, + "title": "Image sizes", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 8, + "y": 55, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "histogram_quantile(0.99, sum by (le) (rate(dims_source_bytes_bucket[1m])))", + "legendFormat": "p99 source", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "histogram_quantile(0.99, sum by (le) (rate(dims_output_bytes_bucket[1m])))", + "legendFormat": "p99 output", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "bytes", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 126, + "title": "ImageMagick time share", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 16, + "y": 55, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "rate(dims_imagemagick_duration_seconds_sum[1m])", + "legendFormat": "imagemagick", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "rate(dims_source_fetch_duration_seconds_sum[1m])", + "legendFormat": "source fetch", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 127, + "title": "Guard and signature", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 62, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 128, + "title": "Network guard refusals", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 63, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (reason) (rate(dims_netguard_refusals_total[1m])) > 0", + "legendFormat": "{{reason}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 129, + "title": "Allowlist checks", + "type": "timeseries", + "description": "Under log, refused is what enforce would reject.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 8, + "y": 63, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (mode, result) (rate(dims_allowlist_checks_total[1m])) > 0", + "legendFormat": "{{mode}} {{result}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 130, + "title": "Signature checks", + "type": "timeseries", + "description": "mismatch means a stale secret. expired means clock drift.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 16, + "y": 63, + "w": 8, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (result) (rate(dims_signature_checks_total[1m])) > 0", + "legendFormat": "{{result}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 131, + "title": "Resources", + "type": "row", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 70, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 132, + "title": "ImageMagick resource use against its limit", + "type": "timeseries", + "description": "Disk rising while memory sits at its ceiling means the pixel cache spilled.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 71, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "dims_imagemagick_resource_bytes{resource=~\"memory|map|disk\"}", + "legendFormat": "{{resource}} used", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "dims_imagemagick_resource_limit_bytes{resource=~\"memory|map|disk\"}", + "legendFormat": "{{resource}} limit", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "bytes", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 133, + "title": "Process memory", + "type": "timeseries", + "description": "The soak watches this line for a trend.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 71, + "w": 12, + "h": 8 + }, + "targets": [ + { + "expr": "dims_process_resident_bytes", + "legendFormat": "resident sum", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "dims_process_resident_max_bytes", + "legendFormat": "widest worker", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "dims_process_virtual_bytes", + "legendFormat": "virtual sum", + "refId": "C", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "bytes", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 134, + "title": "httpd workers by state", + "type": "timeseries", + "description": "Ready near zero while in flight climbs means the pool is full.", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 0, + "y": 79, + "w": 12, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (state) (dims_httpd_workers{state!=\"dead\"})", + "legendFormat": "{{state}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "short", + "custom": { + "lineWidth": 2, + "fillOpacity": 40, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "normal", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + }, + { + "id": 135, + "title": "Overlay cache and error images", + "type": "timeseries", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "PROM" + }, + "gridPos": { + "x": 12, + "y": 79, + "w": 12, + "h": 7 + }, + "targets": [ + { + "expr": "sum by (result) (rate(dims_overlay_cache_lookups_total[1m])) > 0", + "legendFormat": "overlay {{result}}", + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + }, + { + "expr": "sum by (source) (rate(dims_error_images_total[1m])) > 0", + "legendFormat": "error image {{source}}", + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "PROM" + } + } + ], + "fieldConfig": { + "defaults": { + "unit": "ops", + "custom": { + "lineWidth": 2, + "fillOpacity": 12, + "showPoints": "never", + "spanNulls": true, + "stacking": { + "mode": "none", + "group": "A" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + }, + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "showLegend": true, + "calcs": [ + "last", + "max" + ] + }, + "tooltip": { + "mode": "multi", + "sort": "desc" + } + } + } + ] +} \ No newline at end of file diff --git a/test/endurance/observe/grafana/dashboards/provider.yml b/test/endurance/observe/grafana/dashboards/provider.yml new file mode 100644 index 0000000..da19cf2 --- /dev/null +++ b/test/endurance/observe/grafana/dashboards/provider.yml @@ -0,0 +1,7 @@ +apiVersion: 1 + +providers: + - name: mod_dims + type: file + options: + path: /etc/grafana/provisioning/dashboards diff --git a/test/endurance/observe/grafana/datasources/prometheus.yml b/test/endurance/observe/grafana/datasources/prometheus.yml new file mode 100644 index 0000000..6518213 --- /dev/null +++ b/test/endurance/observe/grafana/datasources/prometheus.yml @@ -0,0 +1,9 @@ +apiVersion: 1 + +datasources: + - name: Prometheus + type: prometheus + access: proxy + url: http://prometheus:9090 + isDefault: true + uid: PROM diff --git a/test/endurance/observe/prometheus.yml b/test/endurance/observe/prometheus.yml new file mode 100644 index 0000000..2eee2cd --- /dev/null +++ b/test/endurance/observe/prometheus.yml @@ -0,0 +1,10 @@ +# Scrapes the soak server's metrics port. The soak joins dims-soak-net, and +# the server answers to the alias "dims" on it. +global: + scrape_interval: 5s + evaluation_interval: 5s + +scrape_configs: + - job_name: mod_dims + static_configs: + - targets: ['dims:8001'] diff --git a/test/endurance/observe/up.sh b/test/endurance/observe/up.sh new file mode 100755 index 0000000..cdd5aaa --- /dev/null +++ b/test/endurance/observe/up.sh @@ -0,0 +1,26 @@ +#!/usr/bin/env bash +# +# Starts Prometheus and Grafana against a running soak. +# +# bash test/endurance/observe/up.sh +# +# Copyright 2026 Jeremy Collins +# SPDX-License-Identifier: Apache-2.0 +set -euo pipefail + +HERE="$(cd "$(dirname "$0")" && pwd)" + +if ! docker network inspect dims-soak-net >/dev/null 2>&1; then + echo "dims-soak-net is missing. Start the soak first:" >&2 + echo " bash test/endurance/run.sh" >&2 + exit 1 +fi + +docker compose -f "$HERE/compose.yaml" up -d + +address=$(ip -4 addr show scope global 2>/dev/null \ + | grep -oP 'inet \K[\d.]+' | head -1) + +echo +echo "Grafana: http://${address:-localhost}:3000/d/mod-dims-soak/mod-dims" +echo "Prometheus: docker compose -f $HERE/compose.yaml exec prometheus wget -qO- localhost:9090/-/healthy" diff --git a/test/endurance/run.sh b/test/endurance/run.sh index 7a8f6b2..b886875 100755 --- a/test/endurance/run.sh +++ b/test/endurance/run.sh @@ -117,6 +117,8 @@ server_env+=( -e "DIMS_ALLOW_PRIVATE_ADDRESSES=on" -e "DIMS_STATUS_VERBOSE=on" -e "DIMS_ENCRYPTION_ALGORITHM=$algorithm" + # Port 8001 serves the metrics, so a run can be watched while it runs. + -e "DIMS_METRICS_ENABLED=on" # A child that is never recycled keeps whatever it leaked, so the trend # below measures the module rather than the recycling interval. The # production default is 10000. @@ -162,6 +164,7 @@ if [ "$MODE" = valgrind ]; then --show-leak-kinds=definite,indirect \ --errors-for-leak-kinds=definite,indirect \ --num-callers=40 --error-exitcode=0 \ + --keep-debuginfo=yes \ --suppressions=/build/mod_dims/test/valgrind/dims.supp \ --log-file=/tmp/valgrind.log \ /usr/local/apache2/bin/httpd -X -DFOREGROUND >/dev/null diff --git a/test/http/main.c b/test/http/main.c index 69b04d0..bc3800c 100644 --- a/test/http/main.c +++ b/test/http/main.c @@ -27,6 +27,7 @@ extern const dims_test dims_tests_cache_headers[]; extern const dims_test dims_tests_errors[]; extern const dims_test dims_tests_status[]; extern const dims_test dims_tests_legacy_endpoints[]; +extern const dims_test dims_tests_metrics[]; extern const dims_test dims_tests_no_error_image[]; extern const dims_test dims_tests_source_limit[]; extern const dims_test dims_tests_origin_status[]; @@ -48,6 +49,7 @@ static const dims_test_group groups[] = { { "test_errors.c", dims_tests_errors }, { "test_status.c", dims_tests_status }, { "test_legacy_endpoints.c", dims_tests_legacy_endpoints }, + { "test_metrics.c", dims_tests_metrics }, { "test_no_error_image.c", dims_tests_no_error_image }, { "test_source_limit.c", dims_tests_source_limit }, { "test_origin_status.c", dims_tests_origin_status }, diff --git a/test/http/test_metrics.c b/test/http/test_metrics.c new file mode 100644 index 0000000..361ba13 --- /dev/null +++ b/test/http/test_metrics.c @@ -0,0 +1,525 @@ +/* + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "../lib/common.h" +#include "../lib/prometheus.h" + +/* The server that sets the handler and turns DimsMetricsEnabled off. */ +static const char * +metrics_off_url(void) +{ + const char *from_env = getenv("DIMS_TEST_METRICS_OFF_URL"); + return (from_env != NULL && from_env[0] != '\0') ? from_env + : "http://dims:8009"; +} + +static dims_response * +scrape(void) +{ + char url[512]; + + snprintf(url, sizeof(url), "%s/metrics", dims_base_url()); + + return dims_get_absolute(url); +} + +static void +test_metrics_content_type(void) +{ + dims_response *response = scrape(); + const char *type; + + CHECK_INT(response->status, 200, "the metrics endpoint"); + + type = dims_header_value(response, "Content-Type"); + CHECK(type != NULL && strstr(type, "text/plain") != NULL && + strstr(type, "version=0.0.4") != NULL, + "the Prometheus content type, got %s", type ? type : "none"); + + dims_response_free(response); +} + +/* + * Every line is a comment or a sample. A sample is a name, an optional label + * set in braces, a space, and a value. + */ +static void +test_metrics_format(void) +{ + dims_response *response = scrape(); + char *body; + char *line; + char *state = NULL; + int samples = 0; + + body = malloc(response->body_len + 1); + if (body == NULL) { + FAIL("out of memory"); + dims_response_free(response); + return; + } + + memcpy(body, response->body, response->body_len); + body[response->body_len] = '\0'; + + for (line = strtok_r(body, "\n", &state); line != NULL; + line = strtok_r(NULL, "\n", &state)) { + if (strncmp(line, "# HELP ", 7) == 0 || + strncmp(line, "# TYPE ", 7) == 0) { + continue; + } + + if (strchr(line, ' ') == NULL) { + FAIL("a line with no value: %s", line); + break; + } + + samples++; + } + + CHECK(samples > 50, "the page reports samples, got %d", samples); + + free(body); + dims_response_free(response); +} + +/* A histogram reports a bucket per bound, a +Inf bucket, a sum, and a count. */ +static void +test_metrics_histograms(void) +{ + dims_response *response = scrape(); + + CHECK(dims_prom_contains(response, + "dims_request_duration_seconds_bucket{endpoint=\"dims4\"," + "le=\"+Inf\"}"), + "the request duration +Inf bucket"); + CHECK(dims_prom_contains(response, "dims_request_duration_seconds_sum{"), + "the request duration sum"); + CHECK(dims_prom_contains(response, "dims_request_duration_seconds_count{"), + "the request duration count"); + CHECK(dims_prom_contains(response, "dims_source_bytes_bucket{le=\"16384\"}"), + "a byte bucket"); + + /* A bound prints exactly. Six significant digits round 1048576 to + * 1048580, which names a bucket no dashboard expects. */ + CHECK(dims_prom_contains(response, + "dims_source_bytes_bucket{le=\"1048576\"}"), + "the one megabyte bound"); + CHECK(dims_prom_contains(response, + "dims_source_bytes_bucket{le=\"67108864\"}"), + "the sixty four megabyte bound"); + CHECK(dims_prom_contains(response, "dims_request_duration_seconds_bucket{" + "endpoint=\"dims5\",le=\"0.005\"}"), + "the five millisecond bound"); + + /* A family with no labels prints no braces. */ + CHECK(!dims_prom_contains(response, "_count{} "), + "no empty label set"); + + dims_response_free(response); +} + +/* Every family the block holds appears, whatever its value. */ +static void +test_metrics_families(void) +{ + dims_response *response = scrape(); + static const char *const names[] = { + "# TYPE dims_requests_total counter", + "# TYPE dims_responses_total counter", + "# TYPE dims_requests_in_flight gauge", + "# TYPE dims_origin_responses_total counter", + "# TYPE dims_source_format_total counter", + "# TYPE dims_output_format_total counter", + "# TYPE dims_source_bytes_total counter", + "# TYPE dims_output_bytes_total counter", + "# TYPE dims_imagemagick_duration_seconds histogram", + "# TYPE dims_source_frames histogram", + NULL + }; + int i; + + for (i = 0; names[i] != NULL; i++) { + CHECK(dims_prom_contains(response, names[i]), "%s", names[i]); + } + + dims_response_free(response); +} + +/* The directive is the switch. Off, the handler reports no metrics. */ +static void +test_metrics_disabled(void) +{ + char url[512]; + dims_response *response; + + snprintf(url, sizeof(url), "%s/metrics", metrics_off_url()); + response = dims_get_absolute(url); + + CHECK_INT(response->status, 404, "DimsMetricsEnabled off"); + + dims_response_free(response); +} + +/* + * A request moves its counter. The value is read before and after, because + * other cases in the run share the server and its counters. + */ +static void +test_metrics_counts_a_success(void) +{ + dims_response *before = scrape(); + double was = dims_prom_value(before, + "dims_requests_total{endpoint=\"dims4\",outcome=\"success\"}"); + dims_response *image; + dims_response *after; + + image = dims_request_ops("resize/40x40", "grid.png"); + CHECK_INT(image->status, 200, "the image request"); + dims_response_free(image); + + after = scrape(); + CHECK(dims_prom_value(after, + "dims_requests_total{endpoint=\"dims4\",outcome=\"success\"}") + >= was + 1, + "the success counter moved from %g", was); + CHECK(dims_prom_value(after, + "dims_responses_total{endpoint=\"dims4\",code=\"200\"}") + >= 1, + "the 200 counter"); + + dims_response_free(before); + dims_response_free(after); +} + +/* + * A host outside the allowlist reports its own outcome on /dims3/. That is + * the endpoint that enforces the list. + */ +static void +test_metrics_counts_a_refusal(void) +{ + dims_response *before = scrape(); + double was = dims_prom_value(before, "dims_requests_total{endpoint=\"dims3\"," + "outcome=\"hostname_not_in_whitelist\"}"); + dims_response *refused; + dims_response *after; + + refused = dims_get("/dims3/TEST/resize/40x40/" + "?url=http://notallowed:8080/grid.png"); + dims_response_free(refused); + + after = scrape(); + CHECK(dims_prom_value(after, "dims_requests_total{endpoint=\"dims3\"," + "outcome=\"hostname_not_in_whitelist\"}") >= was + 1, + "the refusal counter moved from %g", was); + CHECK(dims_prom_value(after, + "dims_request_duration_seconds_count{endpoint=\"dims3\"}") + >= 1, + "the duration histogram counted it"); + + dims_response_free(before); + dims_response_free(after); +} + +/* Nothing is in flight while the scrape runs, because the scrape is not. */ +static void +test_metrics_in_flight_settles(void) +{ + dims_response *response = scrape(); + + CHECK_INT((long) dims_prom_value(response, + "dims_requests_in_flight{endpoint=\"dims4\"}"), + 0, "in flight after the request ended"); + + dims_response_free(response); +} + +/* A fetch records its origin status, its size, and the format it read. */ +static void +test_metrics_counts_the_source(void) +{ + dims_response *image = dims_request_ops("resize/40x40", "grid.png"); + dims_response *after; + + CHECK_INT(image->status, 200, "the image request"); + dims_response_free(image); + + after = scrape(); + + CHECK(dims_prom_value(after, "dims_origin_responses_total{code=\"200\"}") + >= 1, + "the origin 200 counter"); + CHECK(dims_prom_value(after, "dims_source_format_total{format=\"png\"}") + >= 1, + "the PNG source counter"); + CHECK(dims_prom_value(after, "dims_source_bytes_total") > 0, + "the source byte total"); + CHECK(dims_prom_value(after, "dims_source_bytes_count") >= 1, + "the source size histogram"); + CHECK(dims_prom_value(after, "dims_source_fetch_duration_seconds_count") + >= 1, + "the fetch duration histogram"); + + dims_response_free(after); +} + +/* A response reports its format, its size, and the ImageMagick time. */ +static void +test_metrics_counts_the_output(void) +{ + dims_response *before = scrape(); + double was = dims_prom_value(before, + "dims_output_format_total{format=\"webp\"}"); + dims_response *image; + dims_response *after; + + image = dims_request_ops("resize/40x40/format/webp", "grid.png"); + CHECK_INT(image->status, 200, "the image request"); + dims_response_free(image); + + after = scrape(); + + CHECK(dims_prom_value(after, "dims_output_format_total{format=\"webp\"}") + >= was + 1, + "the webp output counter moved from %g", was); + CHECK(dims_prom_value(after, "dims_output_bytes_total") > 0, + "the output byte total"); + CHECK(dims_prom_value(after, "dims_output_bytes_count") >= 1, + "the output size histogram"); + CHECK(dims_prom_value(after, "dims_imagemagick_duration_seconds_count") + >= 1, + "the ImageMagick duration histogram"); + + dims_response_free(before); + dims_response_free(after); +} + +/* A single frame source counts in the first bucket. */ +static void +test_metrics_counts_frames(void) +{ + dims_response *image = dims_request_ops("resize/40x40", "grid.png"); + dims_response *after; + + dims_response_free(image); + after = scrape(); + + CHECK(dims_prom_value(after, "dims_source_frames_count") >= 1, + "the frame histogram counted a source"); + CHECK(dims_prom_value(after, "dims_source_frames_bucket{le=\"1\"}") >= 1, + "a single frame source is the first bucket"); + + dims_response_free(after); +} + +/* + * The limits come from the configuration, so the reported ceiling matches what + * dims-test.conf sets. The use is per worker and the endpoint sums the slots. + */ +static void +test_metrics_reports_resources(void) +{ + dims_response *response; + + /* A request first, so a worker has sampled itself. */ + dims_response_free(dims_request_ops("resize/40x40", "grid.png")); + + response = scrape(); + + CHECK_INT((long) dims_prom_value(response, + "dims_imagemagick_resource_limit_bytes{resource=\"memory\"}"), + 536870912, "the memory limit"); + CHECK_INT((long) dims_prom_value(response, + "dims_imagemagick_resource_limit_bytes{resource=\"disk\"}"), + 2147483648L, "the disk limit"); + CHECK(dims_prom_value(response, "dims_workers") >= 1, + "a worker holds a slot"); + CHECK(dims_prom_value(response, "dims_process_resident_bytes") > 0, + "resident memory"); + CHECK(dims_prom_value(response, "dims_process_resident_max_bytes") > 0, + "the widest worker"); + + dims_response_free(response); +} + +/* + * The scoreboard holds a slot per thread across the daemon ceiling, so the + * states add up to the ceiling times the thread count. The scrape itself is a + * busy worker, so at least one is not ready. + */ +static void +test_metrics_reports_the_worker_pool(void) +{ + dims_response *response = scrape(); + static const char *const states[] = { + "dead", "starting", "ready", "busy_read", "busy_write", + "busy_keepalive", "busy_log", "busy_dns", "closing", "graceful", + "idle_kill", NULL + }; + char name[128]; + double total = 0; + double limit; + double threads; + int i; + + for (i = 0; states[i] != NULL; i++) { + snprintf(name, sizeof(name), "dims_httpd_workers{state=\"%s\"}", + states[i]); + total += dims_prom_value(response, name); + } + + limit = dims_prom_value(response, "dims_httpd_processes_limit"); + threads = dims_prom_value(response, "dims_httpd_threads_per_process"); + + CHECK(limit >= 1, "a daemon ceiling"); + CHECK(threads >= 1, "a thread count"); + CHECK_INT((long) total, (long) (limit * threads), + "the worker states add up to the scoreboard"); + + CHECK(dims_prom_value(response, "dims_httpd_processes") >= 1, + "a live process"); + CHECK(dims_prom_value(response, "dims_httpd_workers{state=\"busy_write\"}") + >= 1, + "the scrape is a busy worker"); + + dims_response_free(response); +} + +/* The build gauge names the versions, and the start time is a real clock. */ +static void +test_metrics_reports_the_build(void) +{ + dims_response *response = scrape(); + + CHECK(dims_prom_contains(response, "dims_build_info{version=\""), + "the build gauge"); + CHECK(dims_prom_contains(response, "imagemagick=\"ImageMagick"), + "the ImageMagick version"); + + /* Later than 2020, so the value is a clock rather than an uptime. */ + CHECK(dims_prom_value(response, "dims_start_time_seconds") > 1577836800.0, + "the start time is an epoch second"); + + dims_response_free(response); +} + +/* + * The allowlist check in the handler refuses a /dims3/ request before the + * fetch, so it reports there. The guard runs its own check at fetch time and + * reports every refusal it makes. + */ +static void +test_metrics_counts_the_guard(void) +{ + dims_response *before = scrape(); + double was = dims_prom_value(before, "dims_allowlist_checks_total{" + "mode=\"enforce\",result=\"refused\"}"); + dims_response *after; + + dims_response_free(dims_get("/dims3/TEST/resize/40x40/" + "?url=http://notallowed:8080/grid.png")); + + after = scrape(); + CHECK(dims_prom_value(after, "dims_allowlist_checks_total{" + "mode=\"enforce\",result=\"refused\"}") >= was + 1, + "the allowlist counter moved from %g", was); + CHECK(dims_prom_value(after, "dims_allowlist_checks_total{" + "mode=\"enforce\",result=\"allowed\"}") >= 1, + "an allowed host counts too"); + CHECK(dims_prom_value(after, "dims_source_fetch_total{result=\"refused\"}") + >= 1, + "the guard refuses a fetch of its own"); + + dims_response_free(before); + dims_response_free(after); +} + +/* A signed request that verifies, and one that does not. */ +static void +test_metrics_counts_signatures(void) +{ + dims_response *after; + + dims_response_free(dims_request_ops("resize/40x40", "grid.png")); + + after = scrape(); + CHECK(dims_prom_value(after, "dims_signature_checks_total{" + "endpoint=\"dims4\",result=\"ok\"}") >= 1, + "a signature verified"); + + dims_response_free(after); +} + +/* + * A command counts under its own name. strip runs without a command, so it + * counts under the default trigger. + */ +static void +test_metrics_counts_operations(void) +{ + dims_response *before = scrape(); + double was = dims_prom_value(before, + "dims_operations_total{operation=\"crop\",trigger=\"request\"}"); + dims_response *after; + + dims_response_free(dims_request_ops("crop/40x40+0+0", "grid.png")); + + after = scrape(); + CHECK(dims_prom_value(after, + "dims_operations_total{operation=\"crop\",trigger=\"request\"}") + >= was + 1, + "the crop counter moved from %g", was); + CHECK(dims_prom_value(after, + "dims_operations_total{operation=\"strip\",trigger=\"default\"}") + >= 1, + "strip runs without a command"); + CHECK(dims_prom_value(after, "dims_operation_duration_seconds_count{" + "operation=\"crop\"}") >= 1, + "the crop duration histogram"); + + dims_response_free(after); +} + +/* A failed request sends the error image this server draws. */ +static void +test_metrics_counts_the_error_image(void) +{ + dims_response *after; + + dims_response_free(dims_request_ops("resize/40x40", "missing.png")); + + after = scrape(); + CHECK(dims_prom_value(after, "dims_error_images_total{source=\"fetched\"}") + + dims_prom_value(after, + "dims_error_images_total{source=\"drawn\"}") >= 1, + "an error image was sent"); + + dims_response_free(after); +} + +const dims_test dims_tests_metrics[] = { + { "TestMetricsContentType", test_metrics_content_type, NULL }, + { "TestMetricsFormat", test_metrics_format, NULL }, + { "TestMetricsHistograms", test_metrics_histograms, NULL }, + { "TestMetricsFamilies", test_metrics_families, NULL }, + { "TestMetricsCountsASuccess", test_metrics_counts_a_success, NULL }, + { "TestMetricsCountsARefusal", test_metrics_counts_a_refusal, NULL }, + { "TestMetricsInFlightSettles", test_metrics_in_flight_settles, NULL }, + { "TestMetricsCountsTheSource", test_metrics_counts_the_source, NULL }, + { "TestMetricsCountsTheOutput", test_metrics_counts_the_output, NULL }, + { "TestMetricsCountsFrames", test_metrics_counts_frames, NULL }, + { "TestMetricsReportsResources", test_metrics_reports_resources, NULL }, + { "TestMetricsReportsTheWorkerPool", test_metrics_reports_the_worker_pool, + NULL }, + { "TestMetricsReportsTheBuild", test_metrics_reports_the_build, NULL }, + { "TestMetricsCountsTheGuard", test_metrics_counts_the_guard, NULL }, + { "TestMetricsCountsSignatures", test_metrics_counts_signatures, NULL }, + { "TestMetricsCountsOperations", test_metrics_counts_operations, NULL }, + { "TestMetricsCountsTheErrorImage", test_metrics_counts_the_error_image, + NULL }, + { "TestMetricsDisabled", test_metrics_disabled, NULL }, + DIMS_TEST_END +}; diff --git a/test/http/test_status.c b/test/http/test_status.c index 917646d..95af682 100644 --- a/test/http/test_status.c +++ b/test/http/test_status.c @@ -6,6 +6,7 @@ */ #include "../lib/common.h" +#include "../lib/prometheus.h" static void test_status_is_alive(void) @@ -34,8 +35,55 @@ test_status_hides_versions(void) dims_response_free(response); } +/* + * The two endpoints read the same counters, so the success line matches the + * sum of dims_requests_total across the endpoints. + */ +static void +test_status_agrees_with_the_metrics(void) +{ + dims_response *status; + dims_response *metrics; + const char *line; + char scraped[64]; + double total = 0; + static const char *const endpoints[] = { + "dims3", "dims4", "dims5", "local", NULL + }; + int i; + + dims_response_free(dims_request_ops("resize/40x40", "grid.png")); + + metrics = dims_get("/metrics"); + for (i = 0; endpoints[i] != NULL; i++) { + char name[128]; + + snprintf(name, sizeof(name), + "dims_requests_total{endpoint=\"%s\",outcome=\"success\"}", + endpoints[i]); + total += dims_prom_value(metrics, name); + } + + status = dims_get("/dims-status/"); + line = strstr((const char *) status->body, "Successful requests: "); + + if (line == NULL) { + FAIL("the status page reports no success count"); + } else { + snprintf(scraped, sizeof(scraped), "%s", + line + strlen("Successful requests: ")); + CHECK_INT(atol(scraped), (long) total, + "the status count matches the metrics"); + } + + dims_response_free(status); + dims_response_free(metrics); +} + const dims_test dims_tests_status[] = { { "TestStatusIsAlive", test_status_is_alive, NULL }, + { "TestStatusAgreesWithTheMetrics", test_status_agrees_with_the_metrics, + NULL }, { "TestStatusHidesVersions", test_status_hides_versions, "the versions print unless the directive is set" }, DIMS_TEST_END diff --git a/test/lib/prometheus.c b/test/lib/prometheus.c new file mode 100644 index 0000000..e23caa2 --- /dev/null +++ b/test/lib/prometheus.c @@ -0,0 +1,77 @@ +/* + * Reading a Prometheus exposition body in a case. + * + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "prometheus.h" + +#include +#include + +/* The body with a terminator on the end. The caller frees it. */ +static char * +body_string(const dims_response *response) +{ + char *copy; + + if (response == NULL || response->body == NULL) { + return NULL; + } + + copy = malloc(response->body_len + 1); + if (copy == NULL) { + return NULL; + } + + memcpy(copy, response->body, response->body_len); + copy[response->body_len] = '\0'; + + return copy; +} + +int +dims_prom_contains(const dims_response *response, const char *text) +{ + char *body = body_string(response); + int found; + + if (body == NULL) { + return 0; + } + + found = strstr(body, text) != NULL; + free(body); + + return found; +} + +double +dims_prom_value(const dims_response *response, const char *prefix) +{ + char *body = body_string(response); + size_t len = strlen(prefix); + char *line; + char *state = NULL; + double value = -1; + + if (body == NULL) { + return -1; + } + + for (line = strtok_r(body, "\n", &state); line != NULL; + line = strtok_r(NULL, "\n", &state)) { + /* A sample is the name, its labels, a space, and the value. Comparing + * the space as well keeps dims_requests_total apart from + * dims_requests_total_something. */ + if (strncmp(line, prefix, len) == 0 && line[len] == ' ') { + value = strtod(line + len + 1, NULL); + break; + } + } + + free(body); + + return value; +} diff --git a/test/lib/prometheus.h b/test/lib/prometheus.h new file mode 100644 index 0000000..e29a148 --- /dev/null +++ b/test/lib/prometheus.h @@ -0,0 +1,26 @@ +/* + * Reading a Prometheus exposition body in a case. + * + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#ifndef DIMS_TEST_PROMETHEUS_H +#define DIMS_TEST_PROMETHEUS_H + +#include "request.h" + +/* Whether the body holds the text. The body needs no terminator. */ +int dims_prom_contains(const dims_response *response, const char *text); + +/* + * The value of the sample whose line starts with prefix. A prefix is a metric + * name and its label set: + * + * dims_requests_total{endpoint="dims4",outcome="success"} + * + * Returns -1 when no line starts with it. + */ +double dims_prom_value(const dims_response *response, const char *prefix); + +#endif diff --git a/test/unit/main.c b/test/unit/main.c index 6fd6545..a9f23c6 100644 --- a/test/unit/main.c +++ b/test/unit/main.c @@ -21,6 +21,7 @@ extern const dims_test dims_tests_unit_adjustments[]; extern const dims_test dims_tests_unit_output[]; extern const dims_test dims_tests_unit_watermark[]; extern const dims_test dims_tests_unit_encryption[]; +extern const dims_test dims_tests_unit_metrics[]; extern const dims_test dims_tests_unit_netguard[]; extern const dims_test dims_tests_unit_overlay_cache[]; extern const dims_test dims_tests_unit_param[]; @@ -37,6 +38,7 @@ static const dims_test_group groups[] = { { "unit/test_output.c", dims_tests_unit_output }, { "unit/test_watermark.c", dims_tests_unit_watermark }, { "unit/test_encryption.c", dims_tests_unit_encryption }, + { "unit/test_metrics.c", dims_tests_unit_metrics }, { "unit/test_netguard.c", dims_tests_unit_netguard }, { "unit/test_overlay_cache.c", dims_tests_unit_overlay_cache }, { "unit/test_param.c", dims_tests_unit_param }, diff --git a/test/unit/stub_httpd.c b/test/unit/stub_httpd.c index 78facaa..d7e1641 100644 --- a/test/unit/stub_httpd.c +++ b/test/unit/stub_httpd.c @@ -144,3 +144,14 @@ dims_stub_fixture_dir(void) ? from_env : "/build/mod_dims/test/origin"; } + +/* + * The MPM daemon limit, which sizes the process slots in the metrics block. + * The in-process cases run no MPM, so report one slot. + */ +int +ap_mpm_query(int query_code, int *result) +{ + *result = 1; + return 0; +} diff --git a/test/unit/test_metrics.c b/test/unit/test_metrics.c new file mode 100644 index 0000000..787f68a --- /dev/null +++ b/test/unit/test_metrics.c @@ -0,0 +1,161 @@ +/* + * Copyright 2026 Jeremy Collins + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "../lib/test.h" +#include "../../src/metrics.h" + +#include + +/* + * A bound belongs to its own bucket, because Prometheus buckets are "less than + * or equal to". A value above the last bound belongs to +Inf, which sits at + * index bounds. + */ +static void +test_bucket_boundaries(void) +{ + const dims_bucket_spec *spec = &dims_duration_buckets; + + CHECK_INT(dims_metrics_bucket_index(spec, 0.0), 0, "zero"); + CHECK_INT(dims_metrics_bucket_index(spec, 0.005), 0, "the first bound"); + CHECK_INT(dims_metrics_bucket_index(spec, 0.0051), 1, "just above it"); + CHECK_INT(dims_metrics_bucket_index(spec, 10.0), spec->bounds - 1, + "the last bound"); + CHECK_INT(dims_metrics_bucket_index(spec, 10.1), spec->bounds, + "above the last bound"); +} + +static void +test_byte_and_frame_boundaries(void) +{ + CHECK_INT(dims_metrics_bucket_index(&dims_byte_buckets, 16384), 0, + "16Ki"); + CHECK_INT(dims_metrics_bucket_index(&dims_byte_buckets, 16385), 1, + "just above 16Ki"); + CHECK_INT(dims_metrics_bucket_index(&dims_byte_buckets, 1 << 30), + dims_byte_buckets.bounds, "a gigabyte"); + + CHECK_INT(dims_metrics_bucket_index(&dims_frame_buckets, 1), 0, + "one frame"); + CHECK_INT(dims_metrics_bucket_index(&dims_frame_buckets, 3), 2, + "three frames"); + CHECK_INT(dims_metrics_bucket_index(&dims_frame_buckets, 500), + dims_frame_buckets.bounds, "five hundred frames"); +} + +/* Every bucket table fits the record, which the exposition writer walks. */ +static void +test_bucket_tables_fit(void) +{ + CHECK(dims_duration_buckets.bounds + 1 <= DIMS_BUCKET_MAX, + "the duration table fits"); + CHECK(dims_byte_buckets.bounds + 1 <= DIMS_BUCKET_MAX, + "the byte table fits"); + CHECK(dims_frame_buckets.bounds + 1 <= DIMS_BUCKET_MAX, + "the frame table fits"); +} + +/* + * A bucket holds the observations that fall in it alone. The writer adds them + * up, so the total across the table equals the count. + */ +static void +test_histogram_totals(void) +{ + dims_histogram_rec h; + apr_uint64_t total = 0; + int i; + + memset(&h, 0, sizeof(h)); + + /* Three microseconds, half a second, and a minute. */ + dims_metrics_observe(&h, &dims_duration_buckets, 3); + dims_metrics_observe(&h, &dims_duration_buckets, 500000); + dims_metrics_observe(&h, &dims_duration_buckets, 60000000); + + CHECK_INT((long) h.count, 3, "the count"); + CHECK_INT((long) h.sum, 60500003, "the sum in microseconds"); + + for (i = 0; i < DIMS_BUCKET_MAX; i++) { + total += h.bucket[i]; + } + + CHECK_INT((long) total, 3, "the buckets add up to the count"); + CHECK_INT((long) h.bucket[0], 1, "three microseconds is the first bucket"); + CHECK_INT((long) h.bucket[dims_duration_buckets.bounds], 1, + "a minute is the +Inf bucket"); +} + +/* A byte observation reports bytes, with no division. */ +static void +test_histogram_counts_bytes(void) +{ + dims_histogram_rec h; + + memset(&h, 0, sizeof(h)); + + dims_metrics_observe(&h, &dims_byte_buckets, 2048); + + CHECK_INT((long) h.sum, 2048, "the sum in bytes"); + CHECK_INT((long) h.bucket[0], 1, "two kilobytes is the first bucket"); +} + +static void +test_outcome_index(void) +{ + CHECK_INT(dims_metrics_outcome_index(DIMS_SUCCESS), 0, "success"); + CHECK_INT(dims_metrics_outcome_index(DIMS_NETWORK_REFUSED), + DIMS_OUTCOME_COUNT - 1, "the last status"); + CHECK_INT(dims_metrics_outcome_index(DIMS_IGNORE), DIMS_OUTCOME_COUNT - 1, + "a status outside the table"); + CHECK_STR(dims_metrics_outcome_name(0), "success", "the first name"); +} + +static void +test_code_index(void) +{ + CHECK_STR(dims_metrics_code_name(dims_metrics_code_index(200)), "200", + "a listed code"); + CHECK_STR(dims_metrics_code_name(dims_metrics_code_index(504)), "504", + "the last listed code"); + CHECK_STR(dims_metrics_code_name(dims_metrics_code_index(418)), "other", + "a code outside the list"); +} + +/* DimsOriginStatusMode forward reports whatever the origin returned. */ +static void +test_origin_code_index(void) +{ + CHECK_STR(dims_metrics_origin_code_name(dims_metrics_origin_code_index(304)), + "304", "a listed code"); + CHECK_STR(dims_metrics_origin_code_name(dims_metrics_origin_code_index(451)), + "other", "a code outside the list"); +} + +static void +test_format_index(void) +{ + CHECK_STR(dims_metrics_format_name(dims_metrics_format_index("PNG")), + "png", "an upper case format"); + CHECK_STR(dims_metrics_format_name(dims_metrics_format_index("JPG")), + "jpeg", "JPG names JPEG"); + CHECK_STR(dims_metrics_format_name(dims_metrics_format_index("PCX")), + "other", "a format outside the list"); + CHECK_STR(dims_metrics_format_name(dims_metrics_format_index(NULL)), + "other", "no format"); +} + +const dims_test dims_tests_unit_metrics[] = { + { "TestBucketBoundaries", test_bucket_boundaries, NULL }, + { "TestByteAndFrameBoundaries", test_byte_and_frame_boundaries, NULL }, + { "TestBucketTablesFit", test_bucket_tables_fit, NULL }, + { "TestHistogramTotals", test_histogram_totals, NULL }, + { "TestHistogramCountsBytes", test_histogram_counts_bytes, NULL }, + { "TestOutcomeIndex", test_outcome_index, NULL }, + { "TestCodeIndex", test_code_index, NULL }, + { "TestOriginCodeIndex", test_origin_code_index, NULL }, + { "TestFormatIndex", test_format_index, NULL }, + DIMS_TEST_END +};