Can't get Distributed Tracing to work

[parkee]

Bug Report

What is the issue?

I don't see any traces from my services.

How can it be reproduced?

I'm running a private GKE cluster with empty network policies and workload identity enabled. Container Native Load Balancer is used as an ingress controller.
I have installed linkerd in the linkerd namespace (via Helm) with tracing enabled (slightly modified to push data to stackdriver trace as well as standard jaeger) and HA mode. Also, I have my services running in the separate prod namespace.
Also, added the following annotations to the prod namespace (tried adding to the pod template as well just out of desperation):

    linkerd.io/inject: enabled
    config.linkerd.io/trace-collector: linkerd-collector.linkerd:55678
    config.alpha.linkerd.io/trace-collector-service-account: linkerd-collector

Helm chart has the following related config:

tracing:
  enabled: true
smiMetrics:
  enabled: true
global:
  proxy:
    enableExternalProfiles: true
    trace:
      collectorSvcAddr: "linkerd-collector.linkerd:55678"
      collectorSvcAccount: "linkerd-collector"
    resources:
      cpu:
        limit: "1"
        request: 100m
      memory:
        limit: 250Mi
        request: 20Mi
  controlPlaneTracing: true

Logs, error output, etc

After enabling debug logs and debug proxy I see the following:

  96    90 9.549929790   10.0.4.118 → 10.4.76.48   TCP 68 41234 → 55678 [ACK] Seq=1 Ack=1 Win=331 Len=0 TSval=4008200130 TSecr=568504277
  97    91 9.551256729   10.4.76.48 → 10.0.4.118   TCP 68 [TCP ACKed unseen segment] 55678 → 41234 [ACK] Seq=1 Ack=2 Win=338 Len=0 TSval=568514278 TSecr=4008190089
  98    92 9.578927804   10.0.4.118 → 10.4.146.142 TCP 68 59642 → 8086 [ACK] Seq=1 Ack=1 Win=331 Len=0 TSval=1797062601 TSecr=81780374
  99    93 9.580202705 10.4.146.142 → 10.0.4.118   TCP 68 [TCP ACKed unseen segment] 8086 → 59642 [ACK] Seq=1 Ack=2 Win=339 Len=0 TSval=81790375 TSecr=1797052561
 100    94 9.839197782 10.4.146.142 → 10.0.4.118   TCP 68 [TCP Keep-Alive] [TCP ACKed unseen segment] 8086 → 59642 [ACK] Seq=0 Ack=2 Win=339 Len=0 TSval=81790634 TSecr=1797052561
 101    95 9.839213604   10.0.4.118 → 10.4.146.142 TCP 68 [TCP Previous segment not captured] 59642 → 8086 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=1797062862 TSecr=81790375
 102    96 9.893410405   10.4.76.48 → 10.0.4.118   TCP 68 [TCP Keep-Alive] [TCP ACKed unseen segment] 55678 → 41234 [ACK] Seq=0 Ack=2 Win=338 Len=0 TSval=568514620 TSecr=4008190089
 103    97 9.893429897   10.0.4.118 → 10.4.76.48   TCP 68 [TCP Previous segment not captured] 41234 → 55678 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=4008200474 TSecr=568514278
1212  1206 85.312941118   10.0.4.118 → 10.4.76.48   TCP 68 [TCP Keep-Alive] 41234 → 55678 [ACK] Seq=1 Ack=1 Win=331 Len=0 TSval=4008275888 TSecr=568514278
1213  1207 85.313140540 10.4.146.142 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 8086 → 59642 [ACK] Seq=364 Ack=644 Win=335 Len=0 TSval=81866103 TSecr=1797110221
1214  1208 85.313214990 10.4.182.111 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 8080 → 44876 [ACK] Seq=1 Ack=2 Win=331 Len=0 TSval=2289470537 TSecr=1253883192
1215  1209 85.313221152 10.4.182.111 → 10.0.4.118   TCP 68 [TCP Keep-Alive] 8080 → 44876 [ACK] Seq=0 Ack=2 Win=331 Len=0 TSval=2289470537 TSecr=1253883192
1216  1210 85.313231273   10.0.4.118 → 10.4.182.111 TCP 68 [TCP Keep-Alive ACK] 44876 → 8080 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=1253958450 TSecr=2289470537
1217  1211 85.314049291   10.4.76.48 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 55678 → 41234 [ACK] Seq=1 Ack=2 Win=338 Len=0 TSval=568590035 TSecr=4008200474
1218  1212 86.181443547   10.4.76.48 → 10.0.4.118   TCP 68 [TCP Keep-Alive] 55678 → 41234 [ACK] Seq=0 Ack=2 Win=338 Len=0 TSval=568590903 TSecr=4008200474
1219  1213 86.181465998   10.0.4.118 → 10.4.76.48   TCP 68 [TCP Keep-Alive ACK] 41234 → 55678 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=4008276757 TSecr=568590035
7894  7888 163.135969905   10.0.4.118 → 10.4.76.48   TCP 68 [TCP Keep-Alive] 41234 → 55678 [ACK] Seq=1 Ack=1 Win=331 Len=0 TSval=4008353706 TSecr=568590035
7895  7889 163.136737013 10.4.182.111 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 8080 → 44876 [ACK] Seq=1 Ack=2 Win=331 Len=0 TSval=2289548355 TSecr=1253958450
7896  7890 163.136741265 10.4.182.111 → 10.0.4.118   TCP 68 [TCP Keep-Alive] 8080 → 44876 [ACK] Seq=0 Ack=2 Win=331 Len=0 TSval=2289548355 TSecr=1253958450
7897  7891 163.136749349   10.0.4.118 → 10.4.182.111 TCP 68 [TCP Keep-Alive ACK] 44876 → 8080 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=1254036269 TSecr=2289548355
7898  7892 163.137537687   10.4.76.48 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 55678 → 41234 [ACK] Seq=1 Ack=2 Win=338 Len=0 TSval=568667853 TSecr=4008276757
7899  7893 163.137586548 10.4.146.142 → 10.0.4.118   TCP 68 [TCP Keep-Alive ACK] 8086 → 59642 [ACK] Seq=364 Ack=644 Win=335 Len=0 TSval=81943922 TSecr=1797139657
7900  7894 164.005477639   10.4.76.48 → 10.0.4.118   TCP 68 [TCP Keep-Alive] 55678 → 41234 [ACK] Seq=0 Ack=2 Win=338 Len=0 TSval=568668721 TSecr=4008276757
7901  7895 164.005495636   10.0.4.118 → 10.4.76.48   TCP 68 [TCP Keep-Alive ACK] 41234 → 55678 [ACK] Seq=2 Ack=1 Win=331 Len=0 TSval=4008354575 TSecr=568667853

So looks like there's traffic flowing to the correctly resolved IP and port 55678
The proxy itself has the following logs:

  11 [     0.12219655s]  INFO linkerd2_proxy: OpenCensus tracing collector at linkerd-collector.linkerd:55678 (linkerd-collector.linkerd.serviceaccount.identity.linkerd.cluster.local)
  26 [     0.17826747s] DEBUG daemon:opencensus: linkerd2_app::oc_collector: running peer.addr=ControlAddr { addr: Name(NameAddr { name: "linkerd-collector.linkerd", port: 55678 }), identity: Some("linkerd-collector.linkerd.serviceaccoun
     t.identity.linkerd.cluster.local") }
  27 [     0.17913166s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  28 [     0.17946849s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  29 [     0.17975264s] DEBUG daemon:identity:resolve_one_ip{name=linkerd-identity.linkerd.svc.cluster.local}: trust_dns_proto::xfer::dns_handle: querying: linkerd-identity.linkerd.svc.cluster.local.prod.svc.cluster.local. A
  30 [     0.18089539s] DEBUG daemon:opencensus:resolve_one_ip{name=linkerd-collector.linkerd}: trust_dns_proto::xfer::dns_handle: querying: linkerd-collector.linkerd.prod.svc.cluster.local. A
  31 [     0.18116719s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  32 [     0.18150721s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  33 [     0.17827133s] DEBUG dst:resolve_one_ip{name=linkerd-dst.linkerd.svc.cluster.local}: trust_dns_proto::xfer: enqueueing message: [Query { name: Name { is_fqdn: true, labels: [linkerd-dst, linkerd, svc, cluster, local, catch-prod,
      svc, cluster, local] }, query_type: A, query_class: IN }]
  34 [     0.21118142s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  35 [     0.21139977s] DEBUG trust_dns_proto::xfer::dns_exchange: connection established: UDP(10.4.0.10:53)
  36 [     0.21118975s] DEBUG daemon:identity:resolve_one_ip{name=linkerd-identity.linkerd.svc.cluster.local}: trust_dns_proto::xfer: enqueueing message: [Query { name: Name { is_fqdn: true, labels: [linkerd-identity, linkerd, svc, clust
     er, local, prod, svc, cluster, local] }, query_type: A, query_class: IN }]
  37 [     0.21150081s]  INFO trust_dns_proto::xfer::dns_exchange: sending message via: UDP(10.4.0.10:53)
  38 [     0.21196344s]  INFO trust_dns_proto::xfer::dns_exchange: sending message via: UDP(10.4.0.10:53)
  39 [     0.21211805s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  40 [     0.21209898s] DEBUG daemon:opencensus:resolve_one_ip{name=linkerd-collector.linkerd}: trust_dns_proto::xfer: enqueueing message: [Query { name: Name { is_fqdn: true, labels: [linkerd-collector, linkerd, prod, svc, cluster
     , local] }, query_type: A, query_class: IN }]
  49 [     0.21507616s] DEBUG daemon:opencensus:resolve_one_ip{name=linkerd-collector.linkerd}: trust_dns_proto::udp::udp_stream: created socket: UdpSocket { addr: V4(0.0.0.0:26737), fd: 17 }
  75 [     0.30388824s] DEBUG daemon:opencensus:resolve_one_ip{name=linkerd-collector.linkerd}: trust_dns_proto::xfer::dns_handle: querying: linkerd-collector.linkerd.prod.svc.cluster.local. AAAA
  76 [     0.30419353s] DEBUG daemon:identity:resolve_one_ip{name=linkerd-identity.linkerd.svc.cluster.local}: trust_dns_proto::xfer::dns_handle: querying: linkerd-identity.linkerd.svc.cluster.local.prod.svc.cluster.local. AAAA
  77 [     0.30436134s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  78 [     0.30445427s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  79 [     0.30461583s] DEBUG tokio_reactor: loop process - 1 events, 0.000s
  80 [     0.30476587s] DEBUG daemon:opencensus:resolve_one_ip{name=linkerd-collector.linkerd}: trust_dns_proto::xfer: enqueueing message: [Query { name: Name { is_fqdn: true, labels: [linkerd-collector, linkerd, prod, svc, cluster
     , local] }, query_type: AAAA, query_class: IN }]
  81 [     0.30488222s] DEBUG dst:resolve_one_ip{name=linkerd-dst.linkerd.svc.cluster.local}: trust_dns_proto::rr::record_data: reading SOA
  82 [     0.30527749s] DEBUG dst:resolve_one_ip{name=linkerd-dst.linkerd.svc.cluster.local}: trust_dns_proto::udp::udp_client_stream: received message id: 49261
  83 [     0.30546456s] DEBUG dst:resolve_one_ip{name=linkerd-dst.linkerd.svc.cluster.local}: tokio_reactor: dropping I/O source: 4
 200 [     0.40302054s] DEBUG daemon:opencensus: linkerd2_proxy_transport::tls::client: peer.identity=Some("linkerd-collector.linkerd.serviceaccount.identity.linkerd.cluster.local")
 201 [     0.40319944s] DEBUG daemon:opencensus: linkerd2_proxy_transport::connect: Connecting peer.addr=10.4.76.48:55678

That querying: linkerd-collector.linkerd.prod.svc.cluster.local confuses me as I'm not sure why it has my prod namespace on the path, but at the end looks like it's able to resolve the correct IP (Connecting peer.addr=10.4.76.48:55678)

In the end, I see some linkerd traces in both jaeger and stackdriver, for example:

Recv./apis/tap.linkerd.io/v1alpha1
Recv.io.linkerd.proxy.destination.Destination.Get

etc

But I don't see any traces from my services (in the prod namespace).
I enabled header propagation in my services, but disabled span emission from services (want to see what linkerd-proxy would emit and then enrich with my data if needed).
GRPC is used as a way of communication between services.

Any suggestions on where to look? To me, it looks like there're no issues in configuration and networking as it resolves the IP and makes some connections to the IP and port 55678. But I'm not sure how to figure out why it gets lost later down the road.

At the same time, I see seemingly correct data on the Graphana dashboards (requests, latency, etc)

linkerd check output

kubernetes-api
--------------
√ can initialize the client
√ can query the Kubernetes API

kubernetes-version
------------------
√ is running the minimum Kubernetes API version
√ is running the minimum kubectl version

linkerd-existence
-----------------
√ 'linkerd-config' config map exists
√ heartbeat ServiceAccount exist
√ control plane replica sets are ready
√ no unschedulable pods
√ controller pod is running
√ can initialize the client
√ can query the control plane API

linkerd-config
--------------
√ control plane Namespace exists
√ control plane ClusterRoles exist
√ control plane ClusterRoleBindings exist
√ control plane ServiceAccounts exist
√ control plane CustomResourceDefinitions exist
√ control plane MutatingWebhookConfigurations exist
√ control plane ValidatingWebhookConfigurations exist
√ control plane PodSecurityPolicies exist

linkerd-identity
----------------
√ certificate config is valid
√ trust anchors are using supported crypto algorithm
√ trust anchors are within their validity period
√ trust anchors are valid for at least 60 days
√ issuer cert is using supported crypto algorithm
√ issuer cert is within its validity period
√ issuer cert is valid for at least 60 days
√ issuer cert is issued by the trust anchor

linkerd-api
-----------
√ control plane pods are ready
√ control plane self-check
√ [kubernetes] control plane can talk to Kubernetes
√ [prometheus] control plane can talk to Prometheus
√ tap api service is running

linkerd-version
---------------
√ can determine the latest version
√ cli is up-to-date

control-plane-version
---------------------
√ control plane is up-to-date
√ control plane and cli versions match

linkerd-addons
--------------
√ 'linkerd-config-addons' config map exists

linkerd-grafana
---------------
√ grafana add-on service account exists
√ grafana add-on config map exists
√ grafana pod is running

linkerd-tracing
---------------
√ collector service account exists
√ jaeger service account exists
√ collector config map exists
√ collector pod is running
√ jaeger pod is running

Status check results are √

Environment

• Kubernetes Version: v1.17.6-gke.11
• Cluster Environment: GKE
• Host OS: Container-Optimized OS
• Linkerd version: 2.8.1

[ihcsim]

@parkee Would you mind trying the latest edge release? There is a recent fix in the proxy that may resolve this issue. Keep me posted.

[parkee]

@ihcsim
Unfortunately still nothing. Got a nice (and correct) graph of service dependencies now :) But still no tracing data.
Here's logs from my service's proxy (without debug enabled):

time="2020-07-22T19:03:38Z" level=info msg="running version edge-20.7.3"
[     0.10504551s]  INFO linkerd2_proxy: Admin interface on 0.0.0.0:4191
[     0.10527430s]  INFO linkerd2_proxy: Inbound interface on 0.0.0.0:4143
[     0.10532265s]  INFO linkerd2_proxy: Outbound interface on 127.0.0.1:4140
[     0.10536791s]  INFO linkerd2_proxy: Tap interface on 0.0.0.0:4190
[     0.10545020s]  INFO linkerd2_proxy: Local identity is my-service-account.prod.serviceaccount.identity.linkerd.cluster.local
[     0.10553002s]  INFO linkerd2_proxy: Identity verified via linkerd-identity.linkerd.svc.cluster.local:8080 (linkerd-identity.linkerd.serviceac
count.identity.linkerd.cluster.local)
[     0.10556929s]  INFO linkerd2_proxy: Destinations resolved via linkerd-dst.linkerd.svc.cluster.local:8086 (linkerd-destination.linkerd.service
account.identity.linkerd.cluster.local)
[     0.10560481s]  INFO linkerd2_proxy: OpenCensus tracing collector at linkerd-collector.linkerd:55678 (linkerd-collector.linkerd.serviceaccount
.identity.linkerd.cluster.local)
[     0.11344266s]  INFO outbound: linkerd2_app_outbound: Serving addr=127.0.0.1:4140
[     0.11437443s]  INFO inbound: linkerd2_app_inbound: Serving addr=0.0.0.0:4143
[     1.482986005s]  INFO daemon:identity: linkerd2_app: Certified identity: my-service-account.prod.serviceaccount.identity.linkerd.clus
ter.local
[     4.960774763s]  WARN inbound:accept{peer.addr=10.128.0.39:60708}:source{target.addr=10.0.1.174:8080}: linkerd2_app_core::errors: Failed to pr
oxy request: error trying to connect: Connection refused (os error 111)
[    16.272804467s]  WARN inbound:accept{peer.addr=10.128.0.39:60978}:source{target.addr=10.0.1.174:8080}: linkerd2_app_core::errors: Failed to pr
oxy request: error trying to connect: Connection refused (os error 111)
[   190.507060023s]  INFO outbound:accept{peer.addr=10.0.1.174:53634}:source{target.addr=169.254.169.254:80}: linkerd2_proxy_http::canonicalize: D
NS refinement timed out
[   190.509668092s]  WARN poll_profile: linkerd2_service_profiles::client: Could not fetch profile error=grpc-status: InvalidArgument, grpc-messag
e: "invalid service: name metadata.google.internal does not match cluster domain cluster.local"
[   190.714536352s]  INFO outbound:accept{peer.addr=10.0.1.174:53634}:source{target.addr=169.254.169.254:80}: linkerd2_proxy_http::canonicalize: D
NS refinement timed out

[ihcsim]

There are some error trying to connect: Connection refused errors in the proxy log. Are the services able to talk to each other?

[parkee]

@ihcsim yes, services can talk other, also I tried to kubectl exec inside my service and curl linkerd-collector.linkerd:55678 and it returned 404 (I suppose that's OK for the root URL). And as a said I even see all the data in graphana and when I click Namespace > prod I see the correct graph of services (I suppose it's guessed from requests/responses).
So it looks like networking is fine, I guess that connection error was just a temporary startup issue (not sure why, but I see first 1 or 2 liveness/readiness probes fail with 5xx error, so looks like during startup there's some delay until it has proper configuration).

I wonder what does that one mean: [ 190.509668092s] WARN poll_profile: linkerd2_service_profiles::client: Could not fetch profile error=grpc-status: InvalidArgument, grpc-message: "invalid service: name metadata.google.internal does not match cluster domain cluster.local"
I guess it may be related to the workload identity mechanism. It replaces calls to the Metadata APIs. Could it potentially get in the way?
Any suggestions on how to troubleshoot it further?

[ihcsim]

The warning should be irrelevant - we will need to investigate it separately.

@Pothulapati Any idea where @parkee can't see traces from their services? Header propagation is enabled in their services, but not span emissions. Is that relevant?

[Pothulapati]

@parkee I just tried the demo application with the latest edge, and it works correctly.

But I don't see any traces from my services (in the prod namespace).

Hmm weird, as the logs look okay. Are you sure that you are using b3 propogation i.e opencensus client in your application as per https://linkerd.io/2/tasks/distributed-tracing/#i-dont-see-any-spans-for-the-proxies ?

[parkee]

@Pothulapati
I configured the param in my quarkus services to b3
https://quarkus.io/guides/opentracing#quarkus-jaeger_quarkus.jaeger.propagation

Also, separate question, if some service doesn't support b3 propagation (such as simple service with static resources), in this case, linkerd won't send any spans at all?
If I'm not mistaken istio sends spans in such cases as well, but they're just not a part of the flow (because it doesn't have b3 context in such cases). I'd expect similar behavior here.

[Pothulapati]

@parkee Yep, Linkerd proxy only sends spans if there is a header with b3 propogation format. Can you produce some debug logs of any proxy especially around opencensus with the latest edge? That would be really useful. If you can give us manifests to reproduce this environment, that would be even better :)

I think, We did not go through that route as there is not much use with the proxy spans if you can't see them in the global context. Also. because we don't start traces as we don't do ingress stuff and we don't want to deal with sampling stuff.
But if you feel that it should not be the case,feel free to raise an another issue and we can take it up in more detail :)

[parkee]

@Pothulapati
Sorry, I was a bit busy, I'll try to debug more over the weekend. Maybe there's an issue with quarkus and GRPC call b3 propagation.

Yea, that's a separate discussion, but it would really be cool to have the feature.
For example, now we're using the Container Native Load Balancer in GKE and it doesn't support starting traces.
So in case LB -> Service A -> Service B it looks like I'll never get spans for the Service A, because they won't be created at the LB level and I'll only get spans for the Service B, because Service A will initiate the context internally. Am I correct (for a case when my services themselves won't emit any spans and rely purely on Linkerd)?

[parkee]

@Pothulapati
Basically, it turned out that quarkus has an issue with grpc and doesn't propagate tracing context on grpc calls. I think as soon as it will be resolved I should see some traces for the Service B.
In general, I still can't find a way to see traces for the Services A considering that I don't have much control over the container-native load balancer and there's no way to enable generating trace context from its side.

Also, I want to clarify if I use the correct link to push traces from my app now http://linkerd-collector:55678/api/traces?

[ihcsim]

Can you add and inject an ingress controller in front of service A? LB -> Ingress -> Service A -> Service B

[parkee]

@ihcsim The LB acts as an ingress-controller itself, so even though it may be doable to configure it to first forward traffic to some kind of Ambassador and then to the service, it breaks the whole point of using this LB. So it would be cool to have some way of starting traces at the sidecar level. But I'll also drop a message to Google Cloud support and ask if they have any plans to add tracing support.

Because the container-native load balancer talks directly with the Pods, and connections have fewer network hops, both latency and throughput are improved.

https://cloud.google.com/kubernetes-engine/docs/concepts/container-native-load-balancing
https://cloud.google.com/kubernetes-engine/docs/how-to/container-native-load-balancing

[parkee]

Google Cloud generates only x-cloud-trace-context header (automatically and it's not configurable). Maybe that's possible to add support for such cloud-specific headers in addition to b3?

[ihcsim]

@parkee In the current design, the ingress is where the root span starts. At the moment, there is no plan to support cloud-specific trace headers.