Vizier Pem "Failed to connect to NATS, nats_status=6" & NATS pods terminating

[Robbie558]

Describe the bug

I am deploying via Pixie operator via Helm and facing another issue that appears related to the pl-nats pod/s.

Once the vizier-metadata pod comes up the pl-nats pod/s terminate after ~20 seconds (i assume they are passing their liveness/readiness probe given this timing). Then the vizier-pem pods report the following (kelvin pod also reports similar):

F20230620 15:23:15.315608 1551459 statusor.h:148] Check failed: _s.ok() Bad Status: Unknown : Failed to connect to NATS, nats_status=6

I have tried increasing the pl-nats pod count, but the behaviour persists, and there is no useful logs from the pl-nats pods:

$ kubectl logs -n pl pl-nats-0 --follow
[7] 2023/06/19 19:30:01.646266 [INF] Starting nats-server
[7] 2023/06/19 19:30:01.646383 [INF]   Version:  2.9.17
[7] 2023/06/19 19:30:01.646391 [INF]   Git:      [4f2c9a5]
[7] 2023/06/19 19:30:01.646405 [INF]   Name:     NBCXEHKCGCSRNBM43XQXGD3TGJFQP3NIATOSAGG74CQCK6HILV2E4TVH
[7] 2023/06/19 19:30:01.646443 [INF]   ID:       NBCXEHKCGCSRNBM43XQXGD3TGJFQP3NIATOSAGG74CQCK6HILV2E4TVH
[7] 2023/06/19 19:30:01.646463 [INF] Using configuration file: /etc/nats-config/nats.conf
[7] 2023/06/19 19:30:01.648401 [INF] Starting http monitor on 0.0.0.0:8222
[7] 2023/06/19 19:30:01.648587 [INF] Listening for client connections on 0.0.0.0:4222
[7] 2023/06/19 19:30:01.648601 [INF] TLS required for client connections
[7] 2023/06/19 19:30:01.649319 [INF] Server is ready
[7] 2023/06/19 19:36:18.629639 [INF] Initiating Shutdown...
[7] 2023/06/19 19:36:18.632981 [INF] Server Exiting..

I am able to see the following events from the pl-nats pod, but this doesn't make a great deal of sense, nor does it explain the terminations:

15s         Warning   FailedPreStopHook                 pod/pl-nats-0                                  Exec lifecycle hook ([/bin/sh -c /nats-server -sl=ldm=/var/run/nats/nats.pid && /bin/sleep 60]) for Container "pl-nats" in Pod "pl-nats-0_pl(f2658e64-5d8d-4632-9133-cec9b8d5be00)" failed - error: rpc error: code = Unknown desc = failed to exec in container: failed to start exec "2cf016760be7c1f00852ced2432672f156678ab79b902e983fe3857e96525efc": OCI runtime exec failed: exec failed: unable to start container process: exec: "/bin/sh": stat /bin/sh: no such file or directory: unknown, message: ""

To Reproduce
Steps to reproduce the behavior:

1. Configure a values file for the helm chart
2. Deploy the helm chart against a K8s cluster

Config

values.yaml file:

deployOLM: ""
olmNamespace: "olm"
olmOperatorNamespace: "px-operator"
olmBundleChannel: "stable"
olmCatalogSource:
  annotations: {}
  labels: {}
name: "pixie"
clusterName: "{{ cluster_name }}"
version: ""
deployKey: "{{ pixielabs.deploymentKey }}"
customDeployKeySecret: ""
disableAutoUpdate: false
useEtcdOperator: true
cloudAddr: "{{ pixielabs.webui.url }}"
devCloudNamespace: "{{ pixielabs.webui.namespace }}"
pemMemoryLimit: ""
pemMemoryRequest: ""
dataAccess: "Full"
pod:
  annotations: {}
  labels: {}
  resources: {}
  nodeSelector: {}
patches:
  vizier-metadata: '{"spec": {"template": {"spec": {"containers": [{"name":"app","livenessProbe": {"initialDelaySeconds": 360, "periodSeconds": 30 }}]}}}}'

Expected behaviour
A clear and concise description of what you expected to happen.

All pods come up

App information (please complete the following information):

• Helm Chart - pixie-operator-chart-0.1.4
• K8s cluster version: 1.25

Additional context

I did come across this issue reported via New Relic Forum as well as this one which contains the error message we are seeing. Neither resolutions or the suggestion made here resolve the issue.

[leoncard]

Hi, I've been working with @Robbie558 on the matter. We found that the issue is due to vizier-operator not being able to reach the pl-nats-0 pod.

The vizier-operator pod at the px-operator namespace is killing the pl-nats-0 pod because it gets a connection refused when reaching anything .cluster.local.

time="2023-06-26T16:14:06Z" level=error msg="Error making nats monitoring call" error="Get \"http://10-244-4-133.pl.pod.cluster.local:8222\": dial tcp 127.0.0.1:8222: connect: connection refused"
time="2023-06-26T16:14:06Z" level=info msg="NATS pod was successfully deleted"

Switching ndots to 2 on the clusterserviceversion object, also on the px-operator namespace sorts the issue.

      dnsConfig:
        options:
          - name: ndots
            value: "2"

Another possible fix would be to add a trailing dot on the url called, so instead of 10-244-4-133.pl.pod.cluster.local it would have a dot at the end, looking like 10-244-4-133.pl.pod.cluster.local.

I would suggest either adding an option so that people could restrict the ndots for the vizier-operator pod, or doing the trailing dot, which I think would be preferrable.

Is it something pixie could do?

[JamesMBartlett]

Hi, I've been working with @Robbie558 on the matter. We found that the issue is due to vizier-operator not being able to reach the pl-nats-0 pod.

The vizier-operator pod at the px-operator namespace is killing the pl-nats-0 pod because it gets a connection refused when reaching anything .cluster.local.

time="2023-06-26T16:14:06Z" level=error msg="Error making nats monitoring call" error="Get \"http://10-244-4-133.pl.pod.cluster.local:8222\": dial tcp 127.0.0.1:8222: connect: connection refused"
time="2023-06-26T16:14:06Z" level=info msg="NATS pod was successfully deleted"

It seems like 10-244-4-133.pl.pod.cluster.local is being resolved to 127.0.0.1. This suggests to me that there's something wrong with your cluster's DNS setup.

Switching ndots to 2 on the clusterserviceversion object, also on the px-operator namespace sorts the issue.

      dnsConfig:
        options:
          - name: ndots
            value: "2"

The change to ndots shouldn't be necessary as 10-244-4-133.pl.pod.cluster.local should resolve fine unless something in your DNS search path will resolve with 10-244-4-133.pl.pod.cluster.local prepended to it. This "fix" suggests to me there's something more generally awry with your cluster's DNS setup.

Another possible fix would be to add a trailing dot on the url called, so instead of 10-244-4-133.pl.pod.cluster.local it would have a dot at the end, looking like 10-244-4-133.pl.pod.cluster.local.

I would suggest either adding an option so that people could restrict the ndots for the vizier-operator pod, or doing the trailing dot, which I think would be preferrable.

Is it something pixie could do?

I would like to better understand the root problem before we modify pixie. Could you run:

nslookup -debug <your nats pod IP with dashes>.pl.pod.cluster.local

in any pod in the px-operator namespace (I applied a simple ubuntu pod in the namespace in order to run it).

[Robbie558]

Hey @JamesMBartlett You are correct that the root of the problem was our DNS configuration. When running the nslookup commands from a pod in px-operator namespace were getting the following response:

root@ubuntu:/# nslookup -debug <ip_addr_w_dashes>.pl.pod.cluster.local
Server:		<dns_svc_ip_addr>
Address:	<dns_svc_ip_addr>#53

------------
    QUESTIONS:
	<ip_addr_w_dashes>.pl.pod.cluster.local.px-operator.svc.cluster.local, type = A, class = IN
    ANSWERS:
    AUTHORITY RECORDS:
    ->  cluster.local
	origin = ns.dns.cluster.local
	mail addr = hostmaster.cluster.local
	serial = 1687870710
	refresh = 7200
	retry = 1800
	expire = 86400
	minimum = 30
	ttl = 30
    ADDITIONAL RECORDS:
------------
** server can't find <ip_addr_w_dashes>.pl.pod.cluster.local.px-operator.svc.cluster.local: NXDOMAIN
Server:		<dns_svc_ip_addr>
Address:	<dns_svc_ip_addr>#53

------------
    QUESTIONS:
	<ip_addr_w_dashes>.pl.pod.cluster.local.svc.cluster.local, type = A, class = IN
    ANSWERS:
    AUTHORITY RECORDS:
    ->  cluster.local
	origin = ns.dns.cluster.local
	mail addr = hostmaster.cluster.local
	serial = 1687870710
	refresh = 7200
	retry = 1800
	expire = 86400
	minimum = 30
	ttl = 30
    ADDITIONAL RECORDS:
------------
** server can't find <ip_addr_w_dashes>.pl.pod.cluster.local.svc.cluster.local: NXDOMAIN
Server:		<dns_svc_ip_addr>
Address:	<dns_svc_ip_addr>#53

------------
    QUESTIONS:
	<ip_addr_w_dashes>.pl.pod.cluster.local.cluster.local, type = A, class = IN
    ANSWERS:
    AUTHORITY RECORDS:
    ->  cluster.local
	origin = ns.dns.cluster.local
	mail addr = hostmaster.cluster.local
	serial = 1687870710
	refresh = 7200
	retry = 1800
	expire = 86400
	minimum = 30
	ttl = 30
    ADDITIONAL RECORDS:
------------
** server can't find <ip_addr_w_dashes>.pl.pod.cluster.local.cluster.local: NXDOMAIN
Server:		<dns_svc_ip_addr>
Address:	<dns_svc_ip_addr>#53

------------
    QUESTIONS:
	<ip_addr_w_dashes>.pl.pod.cluster.local.<custom_domain>, type = A, class = IN
    ANSWERS:
    ->  <ip_addr_w_dashes>.pl.pod.cluster.local.<custom_domain>
	internet address = 127.0.0.1
	ttl = 30
    AUTHORITY RECORDS:
    ADDITIONAL RECORDS:
------------
Name:	<ip_addr_w_dashes>.pl.pod.cluster.local.<custom_domain>
Address: 127.0.0.1
------------
    QUESTIONS:
	<ip_addr_w_dashes>.pl.pod.cluster.local.<custom_domain>, type = AAAA, class = IN
    ANSWERS:
    AUTHORITY RECORDS:
    ->  <custom_domain>
	origin = <domain_controller_hostname>.<internal_domain>.local
	mail addr = hostmaster
	serial = 9288
	refresh = 900
	retry = 600
	expire = 86400
	minimum = 300
	ttl = 30
    ADDITIONAL RECORDS:
------------

Note that it always resolves on an address with the custom <custom_domain> domain suffix, even when the URL is incorrect i.e. test.pl.pod.cluster.local.<custom_domain>

The /etc/resolv.conf file on the pod is as follows:

search px-operator.svc.cluster.local svc.cluster.local cluster.local <custom_domain>
nameserver <dns_svc_ip_addr>
options ndots:5

Our coredns config map is fairly standard, and pods are configured with the ClusterFirst DNS policy:

apiVersion: v1
data:
  Corefile: |
    .:53 {
        errors
        health {
           lameduck 5s
        }
        ready
        kubernetes cluster.local in-addr.arpa ip6.arpa {
           pods insecure
           fallthrough in-addr.arpa ip6.arpa
           ttl 30
        }
        prometheus :9153
        forward . /etc/resolv.conf {
           max_concurrent 1000
        }
        cache 30
        loop
        reload
        loadbalance
    }

[JamesMBartlett]

I've opened an issue to track removing cluster.local from the NATS address we use in the operator. This will fix your issue (and also help with more general portability) since if the request is made to <ip>.pl.pod, the DNS search path you have will resolve <ip>.pl.pod.cluster.local before it attempts to resolve <ip>.pl.pod.<custom_domain>. The fix is a little involved on our side because we need to update certs.

In the meantime, I would suggest looking at why your custom domain resolves anything to localhost, since I imagine that might cause issues beyond just this Pixie issue.

Closing this issue in favor of #1581