kubernetes-ingress icon indicating copy to clipboard operation
kubernetes-ingress copied to clipboard

Published 20 hours ago • verified publisher icon nginxinc

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

Open vepatel opened this issue 1 year ago • 3 comments

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:

  1. Deploy IC with above flag
  2. Deploy a grpc app and send requests
  3. Check pod logs

vepatel avatar Jan 30 '24 16:01 vepatel

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 :slightly_smiling_face:

Cheers!

github-actions[bot] avatar Jan 30 '24 16:01 github-actions[bot]

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.

github-actions[bot] avatar Apr 30 '24 01:04 github-actions[bot]

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

tstraley avatar May 08 '24 17:05 tstraley

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 avatar Jul 31 '24 18:07 jjngx

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 avatar Aug 01 '24 17:08 jjngx

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

Future (gRPC latency metrics) development is tracked here

jjngx avatar Aug 02 '24 11:08 jjngx