log_to_metrics generates only the first defined metric

[voronin-ilya]

Bug Report

Describe the bug
I tried to set up metrics generation from an nginx log using the log_to_metrics filter. I need several metrics to be generated from access.log – requests_count, request_time, and upstream_response_time. My config file is below. Unfortunately, only the metric described first in the configuration file is being generated – I’ve swapped them around, and always, in /metrics, only the first one is present. It also seems that after being processed by the first instance of the log_to_metrics filter, message processing stops – it also doesn’t output to stdout, despite the corresponding output being configured. If I comment out all log_to_metrics filters, messages are sent to stdout.

To Reproduce
See configuration file below.

Expected behavior

• All configured metrics are present in /metrics endpoint.
• Log messages are sent to stdout.

Your Environment

• Version used: 3.1.6
• Configuration:

[SERVICE]
    Flush        5
    Daemon       Off
    Log_Level    info
    Parsers_File parsers.conf

[INPUT]
    Name   tail
    Path   /var/log/nginx/*access.log
    Parser nginx
    Tag    log

[FILTER]
    Name         parser
    Match        log
    Key_Name     request
    Parser       request
    Preserve_Key True
    Reserve_Data True

[FILTER]
    Name               log_to_metrics
    Match              log
    Tag                metrics.requests
    Metric_Mode        counter
    Metric_Name        requests
    Metric_Description "Requests count"
    Metric_Namespace   openresty
    Metric_Subsystem   server
    Label_Field        method
    Label_Field        status

[FILTER]
    Name               log_to_metrics
    Match              log
    Tag                metrics.request_time
    Metric_Mode        histogram
    Metric_Name        request_time
    Metric_Description "Openresty response time"
    Metric_Namespace   openresty
    Metric_Subsystem   server
    Value_Field        request_time
    Label_Field        method
    Label_Field        status

[FILTER]
    Name               log_to_metrics
    Match              log
    Tag                metrics.upstream_response_time
    Metric_Mode        histogram
    Metric_Name        upstream_response_time
    Metric_Description "Upstream response time"
    Metric_Namespace   openresty
    Metric_Subsystem   server
    Value_Field        upstream_response_time
    Label_Field        method
    Label_Field        status

[OUTPUT]
    Name  stdout
    Match log

[OUTPUT]
    Name  prometheus_exporter
    Match metrics.*
    Host  0.0.0.0
    Port  2021

• Environment name and version (e.g. Kubernetes? What version?): Standalone Linux host
• Server type and version: EC2
• Operating System and version: Ubuntu 18.04
• Filters and plugins: log_to_metrics

[voronin-ilya]

At second glance, it seems that I'm getting the same metric multiple times:

❯ curl -s http://172.20.0.135:2021/metrics
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 31
openresty_server_requests{method="GET",status="200"} 94
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 32
openresty_server_requests{method="GET",status="200"} 94
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 94
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 95
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 96
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 97
openresty_server_requests{method="HEAD",status="200"} 1

After a few seconds:

❯ curl -s http://172.20.0.135:2021/metrics
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 98
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 99
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 100
openresty_server_requests{method="HEAD",status="200"} 1
# HELP openresty_server_requests "Requests count"
# TYPE openresty_server_requests counter
openresty_server_requests{method="GET",status="403"} 33
openresty_server_requests{method="GET",status="200"} 101
openresty_server_requests{method="HEAD",status="200"} 1

[leonardo-albertovich]

Adderssed with PRs #9252 and #9253

[edsiper]

fixed

[Yifengzis]

fixed

I also encountered similar problems here, the same indicators repeated output several times

Version used: 3.1.7