Network not working on pod boot

sukolenvo · January 19, 2022, 3:19am

With istio sidecar, right after pod is created, network is unavailable for few seconds. Is it expected and know issue?
Without istio sidecar all network requests are successful at all stages.
Container that I am testing with is:

      containers:
        - image: nginx
          name: esp
          command: ["bash"]
          args: ["-c", "while(true); do curl 'google.com'; sleep 1; done"]

In logs I get 1-2 times error:

curl: (7) Failed to connect to google.com port 80: Connection refused

After that all requests are executed successfully.

Full logs:

Error 2022-01-18 09:46:20.689 GMT istio-proxy{"level":"Error", "msg":"accept tcp [::]:15020: use of closed network connection"}
Info 2022-01-18 09:58:03.751 GMT istio-initEnvironment:
Info 2022-01-18 09:58:03.751 GMT istio-init------------
Info 2022-01-18 09:58:03.751 GMT istio-initENVOY_PORT=
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_CAPTURE_PORT=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_INBOUND_INTERCEPTION_MODE=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_INBOUND_TPROXY_MARK=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_INBOUND_TPROXY_ROUTE_TABLE=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_INBOUND_PORTS=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_OUTBOUND_PORTS=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_LOCAL_EXCLUDE_PORTS=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_SERVICE_CIDR=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_SERVICE_EXCLUDE_CIDR=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_META_DNS_CAPTURE=
Info 2022-01-18 09:58:03.751 GMT istio-initISTIO_META_DNS_CONNTRACK_ZONE=
Info 2022-01-18 09:58:03.751 GMT istio-init{}
Info 2022-01-18 09:58:03.751 GMT istio-initVariables:
Info 2022-01-18 09:58:03.751 GMT istio-init----------
Info 2022-01-18 09:58:03.751 GMT istio-initPROXY_PORT=15001
Info 2022-01-18 09:58:03.751 GMT istio-initPROXY_INBOUND_CAPTURE_PORT=15006
Info 2022-01-18 09:58:03.751 GMT istio-initPROXY_TUNNEL_PORT=15008
Info 2022-01-18 09:58:03.751 GMT istio-initPROXY_UID=1337
Info 2022-01-18 09:58:03.751 GMT istio-initPROXY_GID=1337
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_INTERCEPTION_MODE=REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_TPROXY_MARK=1337
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_TPROXY_ROUTE_TABLE=133
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_PORTS_INCLUDE=*
Info 2022-01-18 09:58:03.751 GMT istio-initINBOUND_PORTS_EXCLUDE=15090,15021,15020
Info 2022-01-18 09:58:03.751 GMT istio-initOUTBOUND_IP_RANGES_INCLUDE=*
Info 2022-01-18 09:58:03.751 GMT istio-initOUTBOUND_IP_RANGES_EXCLUDE=
Info 2022-01-18 09:58:03.751 GMT istio-initOUTBOUND_PORTS_INCLUDE=
Info 2022-01-18 09:58:03.751 GMT istio-initOUTBOUND_PORTS_EXCLUDE=6379,5432
Info 2022-01-18 09:58:03.751 GMT istio-initKUBEVIRT_INTERFACES=
Info 2022-01-18 09:58:03.751 GMT istio-initENABLE_INBOUND_IPV6=false
Info 2022-01-18 09:58:03.751 GMT istio-initDNS_CAPTURE=false
Info 2022-01-18 09:58:03.751 GMT istio-initDNS_SERVERS=[],[]
Info 2022-01-18 09:58:03.751 GMT istio-init{}
Info 2022-01-18 09:58:03.751 GMT istio-initWriting following contents to rules file: /tmp/iptables-rules-1642499883751103158.txt744227864
Info 2022-01-18 09:58:03.751 GMT istio-init* nat
Info 2022-01-18 09:58:03.751 GMT istio-init-N ISTIO_INBOUND
Info 2022-01-18 09:58:03.751 GMT istio-init-N ISTIO_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-init-N ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-init-N ISTIO_OUTPUT
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp --dport 15008 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_REDIRECT -p tcp -j REDIRECT --to-ports 15001
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_IN_REDIRECT -p tcp -j REDIRECT --to-ports 15006
Info 2022-01-18 09:58:03.751 GMT istio-init-A PREROUTING -p tcp -j ISTIO_INBOUND
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp --dport 22 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp --dport 15090 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp --dport 15021 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp --dport 15020 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_INBOUND -p tcp -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-init-A OUTPUT -p tcp -j ISTIO_OUTPUT
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -p tcp --dport 6379 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -p tcp --dport 5432 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -o lo -s 127.0.0.6/32 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -o lo ! -d 127.0.0.1/32 -m owner --uid-owner 1337 -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -o lo -m owner ! --uid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -m owner --uid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -o lo ! -d 127.0.0.1/32 -m owner --gid-owner 1337 -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -o lo -m owner ! --gid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -m owner --gid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -d 127.0.0.1/32 -j RETURN
Info 2022-01-18 09:58:03.751 GMT istio-init-A ISTIO_OUTPUT -j ISTIO_REDIRECT
Info 2022-01-18 09:58:03.751 GMT istio-initCOMMIT
Info 2022-01-18 09:58:03.751 GMT istio-init{}
Info 2022-01-18 09:58:03.751 GMT istio-initiptables-restore --noflush /tmp/iptables-rules-1642499883751103158.txt744227864
Info 2022-01-18 09:58:03.755 GMT istio-initWriting following contents to rules file: /tmp/ip6tables-rules-1642499883755730907.txt201446039
Info 2022-01-18 09:58:03.756 GMT istio-init{}
Info 2022-01-18 09:58:03.756 GMT istio-initip6tables-restore --noflush /tmp/ip6tables-rules-1642499883755730907.txt201446039
Info 2022-01-18 09:58:03.757 GMT istio-initiptables-save
Info 2022-01-18 09:58:03.759 GMT istio-init# Generated by iptables-save v1.6.1 on Tue Jan 18 09:58:03 2022
Info 2022-01-18 09:58:03.759 GMT istio-init*nat
Info 2022-01-18 09:58:03.759 GMT istio-init:PREROUTING ACCEPT [0:0]
Info 2022-01-18 09:58:03.759 GMT istio-init:INPUT ACCEPT [0:0]
Info 2022-01-18 09:58:03.759 GMT istio-init:OUTPUT ACCEPT [0:0]
Info 2022-01-18 09:58:03.759 GMT istio-init:POSTROUTING ACCEPT [0:0]
Info 2022-01-18 09:58:03.760 GMT istio-init:ISTIO_INBOUND - [0:0]
Info 2022-01-18 09:58:03.760 GMT istio-init:ISTIO_IN_REDIRECT - [0:0]
Info 2022-01-18 09:58:03.760 GMT istio-init:ISTIO_OUTPUT - [0:0]
Info 2022-01-18 09:58:03.760 GMT istio-init:ISTIO_REDIRECT - [0:0]
Info 2022-01-18 09:58:03.760 GMT istio-init-A PREROUTING -p tcp -j ISTIO_INBOUND
Info 2022-01-18 09:58:03.760 GMT istio-init-A OUTPUT -p tcp -j ISTIO_OUTPUT
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -m tcp --dport 15008 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -m tcp --dport 22 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -m tcp --dport 15090 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -m tcp --dport 15021 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -m tcp --dport 15020 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_INBOUND -p tcp -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_IN_REDIRECT -p tcp -j REDIRECT --to-ports 15006
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -p tcp -m tcp --dport 6379 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -p tcp -m tcp --dport 5432 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -s 127.0.0.6/32 -o lo -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT ! -d 127.0.0.1/32 -o lo -m owner --uid-owner 1337 -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -o lo -m owner ! --uid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -m owner --uid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT ! -d 127.0.0.1/32 -o lo -m owner --gid-owner 1337 -j ISTIO_IN_REDIRECT
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -o lo -m owner ! --gid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -m owner --gid-owner 1337 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -d 127.0.0.1/32 -j RETURN
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_OUTPUT -j ISTIO_REDIRECT
Info 2022-01-18 09:58:03.760 GMT istio-init-A ISTIO_REDIRECT -p tcp -j REDIRECT --to-ports 15001
Info 2022-01-18 09:58:03.760 GMT istio-initCOMMIT
Info 2022-01-18 09:58:03.760 GMT istio-init# Completed on Tue Jan 18 09:58:03 2022
Error 2022-01-18 09:58:04.542 GMT esp % Total % Received % Xferd Average Speed Time Time Time Current
Error 2022-01-18 09:58:04.542 GMT esp Dload Upload Total Spent Left Speed
Error 2022-01-18 09:58:04.567 GMT esp 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0curl: (7) Failed to connect to google.com port 80: Connection refused
Info 2022-01-18 09:58:05.023 GMT istio-proxy{"level":"Info", "msg":"Citadel client using custom root cert: istiod.istio-system.svc:15012", "scope":"citadelclient"}
Info 2022-01-18 09:58:05.067 GMT istio-proxy{"level":"Info ", "msg":"All caches have been synced up in 49.320549ms, marking server ready", "scope":"ads"}
Info 2022-01-18 09:58:05.067 GMT istio-proxy{"level":"Info ", "msg":"SDS server for workload certificates started, listening on "./etc/istio/proxy/SDS"", "scope":"sds"}
Info 2022-01-18 09:58:05.067 GMT istio-proxy{"level":"Info ", "msg":"Initializing with upstream address "istiod.istio-system.svc:15012" and cluster "Kubernetes"", "scope":"xdsproxy"}
Info 2022-01-18 09:58:05.068 GMT istio-proxy{"level":"Info ", "msg":"Start SDS grpc server", "scope":"sds"}
Info 2022-01-18 09:58:05.327 GMT istio-proxy{"level":"Info ", "msg":"connected to upstream XDS server: istiod.istio-system.svc:15012", "scope":"xdsproxy"}
Info 2022-01-18 09:58:05.464 GMT istio-proxy{"level":"Info ", "msg":"ADS: new connection for node:sidecar~10.88.36.122~mock-lb-connector-695d46b7cd-d6xmx.hq-stage~hq-stage.svc.cluster.local-1", "scope":"ads"}
Info 2022-01-18 09:58:05.468 GMT istio-proxy{"level":"Info ", "msg":"ADS: new connection for node:sidecar~10.88.36.122~mock-lb-connector-695d46b7cd-d6xmx.hq-stage~hq-stage.svc.cluster.local-2", "scope":"ads"}
Error 2022-01-18 09:58:05.598 GMT esp % Total % Received % Xferd Average Speed Time Time Time Current
Error 2022-01-18 09:58:05.602 GMT esp Dload Upload Total Spent Left Speed
Error 2022-01-18 09:58:05.625 GMT esp 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0curl: (7) Failed to connect to google.com port 80: Connection refused
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"latency":6.45616933E8, "level":"Info", "msg":"generated new workload certificate", "scope":"cache", "ttl":8.639928689369E13}
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"level":"Info", "msg":"Root cert has changed, start rotating root cert", "scope":"cache"}
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"level":"Info", "msg":"XDS: Incremental Pushing:0 ConnectedEndpoints:2 Version:", "scope":"ads"}
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"level":"Info", "msg":"returned workload trust anchor from cache", "scope":"cache", "ttl":8.6399286512747E13}
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"level":"Info", "msg":"returned workload trust anchor from cache", "scope":"cache", "ttl":8.6399286300945E13}
Info 2022-01-18 09:58:05.713 GMT istio-proxy{"level":"Info", "msg":"returned workload certificate from cache", "scope":"cache", "ttl":8.6399286153057E13}
Info 2022-01-18 09:58:05.714 GMT istio-proxy{"level":"Info", "msg":"SDS: PUSH", "resource":"ROOTCA", "scope":"sds"}
Info 2022-01-18 09:58:05.714 GMT istio-proxy{"level":"Info", "msg":"SDS: PUSH", "resource":"default", "scope":"sds"}
Info 2022-01-18 09:58:05.716 GMT istio-proxy{"level":"Info", "msg":"returned workload trust anchor from cache", "scope":"cache", "ttl":8.6399283457401E13}
Info 2022-01-18 09:58:05.716 GMT istio-proxy{"level":"Info", "msg":"SDS: PUSH", "resource":"ROOTCA", "scope":"sds"}
Error 2022-01-18 09:58:06.643 GMT esp % Total % Received % Xferd Average Speed Time Time Time Current
Error 2022-01-18 09:58:06.643 GMT esp Dload Upload Total Spent Left Speed
Error 2022-01-18 09:58:06.795 GMT esp 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 219 100 219 0 0 1460 0 --:--:-- --:--:-- --:--:-- 1460
Info 2022-01-18 09:58:06.796 GMT esp<HTML><HEAD><meta http-equiv="content-type" content="text/html;charset=utf-8">
Info 2022-01-18 09:58:06.796 GMT esp<TITLE>301 Moved</TITLE></HEAD><BODY>
Info 2022-01-18 09:58:06.796 GMT esp<H1>301 Moved</H1>
Info 2022-01-18 09:58:06.796 GMT espThe document has moved
Info 2022-01-18 09:58:06.796 GMT esp<A HREF="http://www.google.com/">here</A>.

Could this be caused by some missconfiguration we did? Any advise is much appreciated. Thank you

tomhawk · November 20, 2022, 9:05am

this is normal for PODs with init container. the case is the init container starts before the istio-init container (which enables the networking). even if istio-init starts , it takes several seconds till the istio-proxy is in ready state and can pass traffic. you should either annotate your pod to wait for istio-proxy READY state or put a wait-loop in your application code for network to be up.
google: proxy.istio.io/config: '{"holdApplicationUntilProxyStarts": true }'

sukolenvo · November 21, 2022, 12:27am

Thank you very much @tomhawk , I’ve just tested and this fixed the issue!

Topic		Replies	Views
Istio (Envoy-proxy sidecar) is blocking http traffic on port 8088 Networking	20	10256	June 4, 2020
Istio Sidecars Failing to Connect to Pilot Networking	1	480	June 1, 2019
Can no longer hit services after turning on side car injection, but all pods are up Networking	0	332	June 18, 2019
Not able to connect istio ingressgateway from istiod Networking	0	473	June 4, 2023
Pod with Sidecar Fails SSL with External Service	4	2153	August 20, 2019

Network not working on pod boot

Related topics