latency metrics are logging error re missing labels when used with grpc #5010

vepatel · 2024-01-30T16:00:17Z

Describe the bug
when -enable-latency-metrics is used with a grpc app, below errors are getting logged

86.183.140.126 - - [30/Jan/2024:14:46:10 +0000] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 0 25 "-" "grpc-python/1.60.0 grpc-c/37.0.0 (osx; chttp2)" "-"
E0130 14:46:10.826254       1 latency.go:186] cannot record latency for upstream - and server 10.24.0.6:50051: wrong number of labels for upstream -. For labels [service resource_type resource_name resource_namespace], got values: []
86.183.140.126 - - [30/Jan/2024:14:46:13 +0000] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 0 25 "-" "grpc-python/1.60.0 grpc-c/37.0.0 (osx; chttp2)" "-"
E0130 14:46:13.940793       1 latency.go:186] cannot record latency for upstream - and server 10.24.1.9:50051: wrong number of labels for upstream -. For labels [service resource_type resource_name resource_namespace], got values: []
86.183.140.126 - - [30/Jan/2024:14:46:17 +0000] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 0 25 "-" "grpc-python/1.60.0 grpc-c/37.0.0 (osx; chttp2)" "-"
E0130 14:46:17.042461       1 latency.go:186] cannot record latency for upstream - and server 10.24.0.6:50051: wrong number of labels for upstream -. For labels [service resource_type resource_name resource_namespace], got values: []

To Reproduce
Steps to reproduce the behavior:

Deploy IC with above flag
Deploy a grpc app and send requests
Check pod logs

The text was updated successfully, but these errors were encountered:

github-actions · 2024-01-30T16:00:29Z

Hi @vepatel thanks for reporting!

Be sure to check out the docs and the Contributing Guidelines while you wait for a human to take a look at this 🙂

Cheers!

github-actions · 2024-04-30T01:45:44Z

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 10 days.

tstraley · 2024-05-08T17:51:33Z

Can we remove the stale label? This is still an issue.

jjngx · 2024-07-31T18:31:39Z

desired prometheus output:

# HELP nginx_ingress_controller_upstream_server_response_latency_ms Bucketed response times from when NGINX establishes a connection to an upstream server to when the last byte of the response body is received by NGINX
# TYPE nginx_ingress_controller_upstream_server_response_latency_ms histogram
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="1"} 0
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="2"} 0
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="3"} 0
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="4"} 0
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="5"} 0
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="10"} 7
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="20"} 7
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="30"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="40"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="50"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="100"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="200"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="300"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="400"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="500"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="1000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="2000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="3000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="4000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="5000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="10000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="20000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="30000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="40000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="50000"} 8
nginx_ingress_controller_upstream_server_response_latency_ms_bucket{class="nginx",code="200",pod_name="grpc-7cd4ffb85d-pcdcf",resource_name="cafe-illy",resource_namespace="default",resource_type="virtualserver",server="10.244.0.21:50051",service="grpc-svc",upstream="vs_default_cafe-illy_grpc",le="+Inf"} 8

test log:

10.244.0.1 - - [31/Jul/2024:18:25:58 +0000] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 13 "-" "grpcurl/dev-build (no version set) grpc-go/1.61.0" "-"
I20240731 18:25:58.639334       1 latency.go:179] XXXXX => <190>Jul 31 18:25:58 nginx: {"upstreamAddress":"10.244.0.21:50051", "upstreamResponseTime":"0.021", "proxyHost":"-", "upstreamStatus": "200"}
I20240731 18:25:58.640241       1 latency.go:228] ZZZ lm.Upstream name => "vs_default_cafe-illy_grpc"
I20240731 18:25:58.640286       1 latency.go:229] ZZZ label values => [grpc-svc virtualserver cafe-illy default]
I20240731 18:25:58.640325       1 latency.go:230] ZZZ label names => [service resource_type resource_name resource_namespace]
I20240731 18:25:58.640436       1 latency.go:192] YYYYY label values => [vs_default_cafe-illy_grpc 10.244.0.21:50051 200 grpc-svc virtualserver cafe-illy default grpc-7cd4ffb85d-pcdcf]

Note: source of the issue: incorrectly created proxyHost name; current: -, expected vs_default_cafe-illy_grpc

Generated config:

nginx@nginx-ingress-86b67478f8-7hqbk:/etc/nginx/conf.d$ cat vs_default_cafe-illy.conf

upstream vs_default_cafe-illy_grpc {
    zone vs_default_cafe-illy_grpc 512k;
    random two least_conn;
    server 10.244.0.21:50051 max_fails=1 fail_timeout=10s max_conns=0;


}


server {
    listen 80;
    listen [::]:80;


    server_name greeter.example.com;
    status_zone greeter.example.com;
    set $resource_type "virtualserver";
    set $resource_name "cafe-illy";
    set $resource_namespace "default";
    listen 443 ssl;
    listen [::]:443 ssl;

    http2 on;
    ssl_certificate $secret_dir_path/default-greeter-secret;
    ssl_certificate_key $secret_dir_path/default-greeter-secret;

    server_tokens "on";




    location /helloworld.Greeter {
        set $service "grpc-svc";
        status_zone "grpc-svc";


        error_page 400 = @grpc_internal;
        error_page 401 = @grpc_unauthenticated;
        error_page 403 = @grpc_permission_denied;
        error_page 404 = @grpc_unimplemented;
        error_page 429 = @grpc_unavailable;
        error_page 502 = @grpc_unavailable;
        error_page 503 = @grpc_unavailable;
        error_page 504 = @grpc_unavailable;
        error_page 405 = @grpc_internal;
        error_page 408 = @grpc_deadline_exceeded;
        error_page 413 = @grpc_resource_exhausted;
        error_page 414 = @grpc_resource_exhausted;
        error_page 415 = @grpc_internal;
        error_page 426 = @grpc_internal;
        error_page 495 = @grpc_unauthenticated;
        error_page 496 = @grpc_unauthenticated;
        error_page 497 = @grpc_internal;
        error_page 500 = @grpc_internal;
        error_page 501 = @grpc_internal;
        set $default_connection_header close;
        grpc_connect_timeout 60s;
        grpc_read_timeout 60s;
        grpc_send_timeout 60s;
        client_max_body_size 1m;

        proxy_buffering on;
        grpc_set_header X-Real-IP $remote_addr;
        grpc_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        grpc_set_header X-Forwarded-Host $host;
        grpc_set_header X-Forwarded-Port $server_port;
        grpc_set_header X-Forwarded-Proto $scheme;
        grpc_set_header Host "$host";
        grpc_pass grpc://vs_default_cafe-illy_grpc;
        grpc_next_upstream error timeout;
        grpc_next_upstream_timeout 0s;
        grpc_next_upstream_tries 0;
    }

	location @grpc_deadline_exceeded {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 4;
        add_header grpc-message 'deadline exceeded';
        return 204;
    }

    location @grpc_permission_denied {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 7;
        add_header grpc-message 'permission denied';
        return 204;
    }

    location @grpc_resource_exhausted {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 8;
        add_header grpc-message 'resource exhausted';
        return 204;
    }

    location @grpc_unimplemented {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 12;
        add_header grpc-message unimplemented;
        return 204;
    }

    location @grpc_internal {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 13;
        add_header grpc-message 'internal error';
        return 204;
    }

    location @grpc_unavailable {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 14;
        add_header grpc-message unavailable;
        return 204;
    }

    location @grpc_unauthenticated {
        default_type application/grpc;
        add_header content-type application/grpc;
        add_header grpc-status 16;
        add_header grpc-message unauthenticated;
        return 204;
    }



}

jjngx · 2024-08-01T17:07:19Z

logs, grpc svc vs http svc:

10.244.0.1 - - [01/Aug/2024:17:04:48 +0000] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 13 "-" "grpcurl/dev-build (no version set) grpc-go/1.61.0" "-"
I20240801 17:04:48.984031       1 latency.go:179] XXXXX syslogMsg => <190>Aug  1 17:04:48 nginx: {"upstreamAddress":"10.244.0.21:50051", "upstreamResponseTime":"0.006", "proxyHost":"-", "upstreamStatus": "200"}
I20240801 17:04:48.984083       1 latency.go:228] ZZZ lm.Upstream name => "-"
I20240801 17:04:48.984099       1 latency.go:229] ZZZ label values => []
I20240801 17:04:48.984107       1 latency.go:230] ZZZ label names => [service resource_type resource_name resource_namespace]
I20240801 17:04:48.984124       1 latency.go:192] YYYYY label values => []
E20240801 17:04:48.984126       1 latency.go:195] cannot record latency for upstream - and server 10.244.0.21:50051: wrong number of labels for upstream -. For labels [service resource_type resource_name resource_namespace], got values: []
10.244.0.1 - - [01/Aug/2024:17:04:59 +0000] "GET /tea HTTP/2.0" 200 155 "-" "curl/7.74.0" "-"
I20240801 17:04:59.386197       1 latency.go:179] XXXXX syslogMsg => <190>Aug  1 17:04:59 nginx: {"upstreamAddress":"10.244.0.30:8080", "upstreamResponseTime":"0.009", "proxyHost":"vs_default_cafe_tea", "upstreamStatus": "200"}
I20240801 17:04:59.386264       1 latency.go:228] ZZZ lm.Upstream name => "vs_default_cafe_tea"
I20240801 17:04:59.386282       1 latency.go:229] ZZZ label values => [tea-svc virtualserver cafe default]
I20240801 17:04:59.386298       1 latency.go:230] ZZZ label names => [service resource_type resource_name resource_namespace]
I20240801 17:04:59.387107       1 latency.go:192] YYYYY label values => [vs_default_cafe_tea 10.244.0.30:8080 200 tea-svc virtualserver cafe default tea-596697966f-4kbmc]

jjngx · 2024-08-02T11:10:29Z

cc / @shaun-nx @brianehlert @vepatel @tstraley @jasonwilliams14

Future (gRPC latency metrics) development is tracked here

vepatel added the backlog Pull requests/issues that are backlog items label Jan 30, 2024

vepatel added the bug An issue reporting a potential bug label Jan 30, 2024

github-actions bot added the stale Pull requests/issues with no activity label Apr 30, 2024

jasonwilliams14 removed the stale Pull requests/issues with no activity label May 8, 2024

brianehlert added this to the v3.6.0 milestone May 8, 2024

brianehlert added the ready for refinement An issue that was triaged and it is ready to be refined label May 8, 2024

pdabelf5 mentioned this issue May 23, 2024

warnings spamming logs: "wrong number of labels for upstream peer, empty labels will be used instead" in nginx-plus ingress controller #5607

Closed

shaun-nx modified the milestones: v3.6.0, Candidates Jul 11, 2024

danielnginx added refined Issues that are ready to be prioritized and removed ready for refinement An issue that was triaged and it is ready to be refined labels Jul 11, 2024

danielnginx modified the milestones: Candidates, v3.7.0 Jul 24, 2024

jjngx self-assigned this Jul 29, 2024

jjngx mentioned this issue Aug 2, 2024

Don't log errors for not implemented grpc metrics #6125

Merged

6 tasks

jjngx linked a pull request Aug 2, 2024 that will close this issue

Don't log errors for not implemented grpc metrics #6125

Merged

6 tasks

jjngx closed this as completed in #6125 Aug 6, 2024

shaun-nx mentioned this issue Jan 21, 2025

Expose latency metrics for gRPC services in Prometheus #6124

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

latency metrics are logging error re missing labels when used with grpc #5010

latency metrics are logging error re missing labels when used with grpc #5010

vepatel commented Jan 30, 2024 •

edited by jjngx

Loading

github-actions bot commented Jan 30, 2024

github-actions bot commented Apr 30, 2024

tstraley commented May 8, 2024

jjngx commented Jul 31, 2024 •

edited

Loading

jjngx commented Aug 1, 2024

jjngx commented Aug 2, 2024 •

edited

Loading

latency metrics are logging error re missing labels when used with grpc #5010

latency metrics are logging error re missing labels when used with grpc #5010

Comments

vepatel commented Jan 30, 2024 • edited by jjngx Loading

github-actions bot commented Jan 30, 2024

github-actions bot commented Apr 30, 2024

tstraley commented May 8, 2024

jjngx commented Jul 31, 2024 • edited Loading

jjngx commented Aug 1, 2024

jjngx commented Aug 2, 2024 • edited Loading

vepatel commented Jan 30, 2024 •

edited by jjngx

Loading

jjngx commented Jul 31, 2024 •

edited

Loading

jjngx commented Aug 2, 2024 •

edited

Loading