CI: multiple tests, level=error msg="Failed to update lock: etcdserver: request timed out" subsys=klog in operator logs #23047
Description
Test Name
K8sAgentHubbleTest Hubble Observe Test L3/L4 Flow
K8sAgentIstioTest Istio Bookinfo Demo Tests bookinfo inter-service connectivityFailure Output
level=error msg="Failed to update lock: etcdserver: request timed out" subsys=klogStack Trace
/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test/ginkgo-ext/scopes.go:415
Found 1 io.cilium/app=operator logs matching list of errors that must be investigated:
level=error
/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test/ginkgo-ext/scopes.go:413Standard Output
Number of "context deadline exceeded" in logs: 3
Number of "level=error" in logs: 0
Number of "level=warning" in logs: 3
Number of "Cilium API handler panicked" in logs: 0
Number of "Goroutine took lock for more than" in logs: 0
Top 1 errors/warnings:
Failed to create peer client for peers synchronization; will try again after the timeout has expired
⚠️ Found "level=error" in logs 1 times
Number of "context deadline exceeded" in logs: 0
Number of "level=error" in logs: 1
Number of "level=warning" in logs: 1
Number of "Cilium API handler panicked" in logs: 0
Number of "Goroutine took lock for more than" in logs: 0
Top 2 errors/warnings:
Failed to update lock: etcdserver: request timed out
Network status error received, restarting client connections
Number of "context deadline exceeded" in logs: 0
Number of "level=error" in logs: 0
⚠️ Number of "level=warning" in logs: 7
Number of "Cilium API handler panicked" in logs: 0
Number of "Goroutine took lock for more than" in logs: 0
Top 3 errors/warnings:
Key allocation attempt failed
Unable to get node resource
Waiting for k8s node information
Cilium pods: [cilium-cw5zw cilium-f9tbx]
Netpols loaded:
CiliumNetworkPolicies loaded:
Endpoint Policy Enforcement:
Pod Ingress Egress
app2-58757b7dd5-khgdb false false
app3-5d69599cdd-sj9vp false false
grafana-d69c97b9b-d7t4g false false
prometheus-655fb888d7-5lr2c false false
coredns-7c74c644b-7q5h2 false false
hubble-relay-668cc97799-nxfsq false false
app1-786c6d794d-c4257 false false
app1-786c6d794d-znhtj false false
Cilium agent 'cilium-cw5zw': Status: Ok Health: Ok Nodes "" ContainerRuntime: Kubernetes: Ok KVstore: Ok Controllers: Total 34 Failed 0
Cilium agent 'cilium-f9tbx': Status: Ok Health: Ok Nodes "" ContainerRuntime: Kubernetes: Ok KVstore: Ok Controllers: Total 34 Failed 0Standard Error
14:14:07 STEP: Running BeforeAll block for EntireTestsuite
14:14:07 STEP: Starting tests: command line parameters: {Reprovision:false HoldEnvironment:false PassCLIEnvironment:true SSHConfig: ShowCommands:false TestScope: SkipLogGathering:false CiliumImage:quay.io/cilium/cilium-ci CiliumTag:ad114844ced0cd19d45b311b1edf4e8feea5413d CiliumOperatorImage:quay.io/cilium/operator CiliumOperatorTag:ad114844ced0cd19d45b311b1edf4e8feea5413d CiliumOperatorSuffix:-ci HubbleRelayImage:quay.io/cilium/hubble-relay-ci HubbleRelayTag:ad114844ced0cd19d45b311b1edf4e8feea5413d ProvisionK8s:true Timeout:2h50m0s Kubeconfig:/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test/vagrant-kubeconfig KubectlPath:/tmp/kubectl RegistryCredentials: Multinode:true RunQuarantined:false Help:false} environment variables: [JENKINS_HOME=/var/jenkins_home GIT_PREVIOUS_SUCCESSFUL_COMMIT=80af06ee3c224f529961cd5ac546de27516ccb10 VM_MEMORY=8192 MAIL=/var/mail/root SSH_CLIENT=54.148.123.155 48544 22 USER=root PROJ_PATH=src/github.com/cilium/cilium RUN_CHANGES_DISPLAY_URL=https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/1706/display/redirect?page=changes NETNEXT=0 SHLVL=1 CILIUM_TAG=ad114844ced0cd19d45b311b1edf4e8feea5413d NODE_LABELS=baremetal ginkgo nightly node-on-jaybird vagrant HUDSON_URL=https://jenkins.cilium.io/ GIT_COMMIT=ad114844ced0cd19d45b311b1edf4e8feea5413d OLDPWD=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9 GINKGO_TIMEOUT=170m HOME=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9 BUILD_URL=https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/1706/ HUDSON_COOKIE=77146a76-5f0b-4819-8b7a-9d07c990a884 JENKINS_SERVER_COOKIE=durable-75dd98290da680aca599366391687855 DOCKER_TAG=ad114844ced0cd19d45b311b1edf4e8feea5413d JobKernelVersion=49 DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/0/bus KERNEL=49 CONTAINER_RUNTIME=docker WORKSPACE=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9 K8S_NODES=2 TESTDIR=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test LOGNAME=root NODE_NAME=node-on-jaybird _=/usr/bin/java HUBBLE_RELAY_IMAGE=quay.io/cilium/hubble-relay-ci STAGE_NAME=BDD-Test-PR GIT_BRANCH=origin/master EXECUTOR_NUMBER=0 TERM=xterm XDG_SESSION_ID=4 HOST_FIREWALL=0 CILIUM_OPERATOR_TAG=ad114844ced0cd19d45b311b1edf4e8feea5413d BUILD_DISPLAY_NAME=#1706 HUDSON_HOME=/var/jenkins_home JOB_BASE_NAME=cilium-master-k8s-1.20-kernel-4.9 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/local/go/bin:/root/go/bin KUBECONFIG=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test/vagrant-kubeconfig FOCUS=K8s BUILD_ID=1706 XDG_RUNTIME_DIR=/run/user/0 BUILD_TAG=jenkins-cilium-master-k8s-1.20-kernel-4.9-1706 RUN_QUARANTINED=false CILIUM_IMAGE=quay.io/cilium/cilium-ci JENKINS_URL=https://jenkins.cilium.io/ LANG=C.UTF-8 JOB_URL=https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/ GIT_URL=https://github.com/cilium/cilium.git BUILD_NUMBER=1706 JENKINS_NODE_COOKIE=ebca5940-de1a-4074-b9d6-c68c9e49bbaf SHELL=/bin/bash GOPATH=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9 RUN_DISPLAY_URL=https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/1706/display/redirect IMAGE_REGISTRY=quay.io/cilium FAILFAST=false HUDSON_SERVER_COOKIE=693c250bfb7e85bf JOB_DISPLAY_URL=https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/display/redirect K8S_VERSION=1.20 JOB_NAME=cilium-master-k8s-1.20-kernel-4.9 PWD=/home/jenkins/workspace/cilium-master-k8s-1.20-kernel-4.9/src/github.com/cilium/cilium/test SSH_CONNECTION=54.148.123.155 48544 145.40.77.217 22 GIT_PREVIOUS_COMMIT=80af06ee3c224f529961cd5ac546de27516ccb10 CILIUM_OPERATOR_IMAGE=quay.io/cilium/operator HUBBLE_RELAY_TAG=ad114844ced0cd19d45b311b1edf4e8feea5413d JobK8sVersion=1.20 VM_CPUS=3 CILIUM_OPERATOR_SUFFIX=-ci]
14:14:07 STEP: Ensuring the namespace kube-system exists
14:14:07 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=cilium-test-logs")
14:14:10 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=cilium-test-logs") => <nil>
14:14:10 STEP: Preparing cluster
14:14:10 STEP: Labelling nodes
14:14:10 STEP: Cleaning up Cilium components
14:14:11 STEP: Running BeforeAll block for EntireTestsuite K8sAgentHubbleTest Hubble Observe
14:14:11 STEP: Ensuring the namespace kube-system exists
14:14:11 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=cilium-test-logs")
14:14:11 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=cilium-test-logs") => <nil>
14:14:11 STEP: Installing Cilium
14:14:13 STEP: Waiting for Cilium to become ready
14:15:53 STEP: Restarting unmanaged pods coredns-7c74c644b-fqnrc in namespace kube-system
14:16:07 STEP: Validating if Kubernetes DNS is deployed
14:16:07 STEP: Checking if deployment is ready
14:16:07 STEP: Kubernetes DNS is not ready: only 0 of 1 replicas are available
14:16:07 STEP: Restarting Kubernetes DNS (-l k8s-app=kube-dns)
14:16:07 STEP: Waiting for Kubernetes DNS to become operational
14:16:07 STEP: Checking if deployment is ready
14:16:07 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:08 STEP: Checking if deployment is ready
14:16:08 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:09 STEP: Checking if deployment is ready
14:16:09 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:10 STEP: Checking if deployment is ready
14:16:10 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:11 STEP: Checking if deployment is ready
14:16:11 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:12 STEP: Checking if deployment is ready
14:16:12 STEP: Kubernetes DNS is not ready yet: only 0 of 1 replicas are available
14:16:13 STEP: Checking if deployment is ready
14:16:13 STEP: Checking if kube-dns service is plumbed correctly
14:16:13 STEP: Checking if pods have identity
14:16:13 STEP: Checking if DNS can resolve
14:16:17 STEP: Kubernetes DNS is not ready yet: CiliumEndpoint does not exist
14:16:17 STEP: Checking if deployment is ready
14:16:17 STEP: Checking if kube-dns service is plumbed correctly
14:16:17 STEP: Checking if pods have identity
14:16:17 STEP: Checking if DNS can resolve
14:16:21 STEP: Validating Cilium Installation
14:16:21 STEP: Performing Cilium controllers preflight check
14:16:21 STEP: Performing Cilium health check
14:16:21 STEP: Performing Cilium status preflight check
14:16:21 STEP: Checking whether host EP regenerated
14:16:28 STEP: Performing Cilium service preflight check
14:16:28 STEP: Performing K8s service preflight check
14:16:34 STEP: Waiting for cilium-operator to be ready
14:16:34 STEP: WaitforPods(namespace="kube-system", filter="-l name=cilium-operator")
14:16:34 STEP: WaitforPods(namespace="kube-system", filter="-l name=cilium-operator") => <nil>
14:16:34 STEP: Waiting for hubble-relay to be ready
14:16:34 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=hubble-relay")
14:16:34 STEP: WaitforPods(namespace="kube-system", filter="-l k8s-app=hubble-relay") => <nil>
14:16:34 STEP: Deleting namespace 202301101416k8sagenthubbletesthubbleobservetestl3l4flow
14:16:35 STEP: Creating namespace 202301101416k8sagenthubbletesthubbleobservetestl3l4flow
14:16:35 STEP: WaitforPods(namespace="202301101416k8sagenthubbletesthubbleobservetestl3l4flow", filter="-l zgroup=testapp")
14:16:43 STEP: WaitforPods(namespace="202301101416k8sagenthubbletesthubbleobservetestl3l4flow", filter="-l zgroup=testapp") => <nil>
=== Test Finished at 2023-01-10T14:16:44Z====
14:16:44 STEP: Running JustAfterEach block for EntireTestsuite K8sAgentHubbleTest Hubble Observe
FAIL: Found 1 io.cilium/app=operator logs matching list of errors that must be investigated:
level=error
===================== TEST FAILED =====================
14:16:44 STEP: Running AfterFailed block for EntireTestsuite K8sAgentHubbleTest Hubble Observe
cmd: kubectl get pods -o wide --all-namespaces
Exitcode: 0
Stdout:
NAMESPACE NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES
202301101416k8sagenthubbletesthubbleobservetestl3l4flow app1-786c6d794d-c4257 2/2 Running 0 14s 10.0.0.106 k8s1 <none> <none>
202301101416k8sagenthubbletesthubbleobservetestl3l4flow app1-786c6d794d-znhtj 2/2 Running 0 14s 10.0.0.96 k8s1 <none> <none>
202301101416k8sagenthubbletesthubbleobservetestl3l4flow app2-58757b7dd5-khgdb 1/1 Running 0 14s 10.0.0.254 k8s1 <none> <none>
202301101416k8sagenthubbletesthubbleobservetestl3l4flow app3-5d69599cdd-sj9vp 1/1 Running 0 14s 10.0.0.56 k8s1 <none> <none>
cilium-monitoring grafana-d69c97b9b-d7t4g 1/1 Running 0 2m38s 10.0.1.154 k8s2 <none> <none>
cilium-monitoring prometheus-655fb888d7-5lr2c 1/1 Running 0 2m38s 10.0.1.253 k8s2 <none> <none>
kube-system cilium-cw5zw 1/1 Running 0 2m36s 192.168.56.12 k8s2 <none> <none>
kube-system cilium-f9tbx 1/1 Running 0 2m36s 192.168.56.11 k8s1 <none> <none>
kube-system cilium-operator-5c5d9d498f-m4nww 1/1 Running 0 2m36s 192.168.56.12 k8s2 <none> <none>
kube-system cilium-operator-5c5d9d498f-t7c6j 1/1 Running 1 2m36s 192.168.56.11 k8s1 <none> <none>
kube-system coredns-7c74c644b-7q5h2 1/1 Running 0 42s 10.0.1.95 k8s2 <none> <none>
kube-system etcd-k8s1 1/1 Running 0 6m54s 192.168.56.11 k8s1 <none> <none>
kube-system hubble-relay-668cc97799-nxfsq 1/1 Running 0 2m36s 10.0.1.94 k8s2 <none> <none>
kube-system kube-apiserver-k8s1 1/1 Running 0 6m54s 192.168.56.11 k8s1 <none> <none>
kube-system kube-controller-manager-k8s1 1/1 Running 3 6m54s 192.168.56.11 k8s1 <none> <none>
kube-system kube-proxy-768lx 1/1 Running 0 6m42s 192.168.56.11 k8s1 <none> <none>
kube-system kube-proxy-q8gmw 1/1 Running 0 3m12s 192.168.56.12 k8s2 <none> <none>
kube-system kube-scheduler-k8s1 0/1 Running 4 6m54s 192.168.56.11 k8s1 <none> <none>
kube-system log-gatherer-85mdt 1/1 Running 0 2m42s 192.168.56.12 k8s2 <none> <none>
kube-system log-gatherer-gmqr4 1/1 Running 0 2m42s 192.168.56.11 k8s1 <none> <none>
kube-system registry-adder-px882 1/1 Running 0 3m10s 192.168.56.11 k8s1 <none> <none>
kube-system registry-adder-zcw4w 1/1 Running 0 3m10s 192.168.56.12 k8s2 <none> <none>
Stderr:
Fetching command output from pods [cilium-cw5zw cilium-f9tbx]
cmd: kubectl exec -n kube-system cilium-cw5zw -c cilium-agent -- cilium endpoint list
Exitcode: 0
Stdout:
ENDPOINT POLICY (ingress) POLICY (egress) IDENTITY LABELS (source:key[=value]) IPv6 IPv4 STATUS
ENFORCEMENT ENFORCEMENT
718 Disabled Disabled 4 reserved:health fd02::19d 10.0.1.53 ready
1179 Disabled Disabled 20437 k8s:app=grafana fd02::130 10.0.1.154 ready
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=default
k8s:io.kubernetes.pod.namespace=cilium-monitoring
1213 Disabled Disabled 1 k8s:cilium.io/ci-node=k8s2 ready
reserved:host
1767 Disabled Disabled 42620 k8s:app=prometheus fd02::16d 10.0.1.253 ready
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=prometheus-k8s
k8s:io.kubernetes.pod.namespace=cilium-monitoring
1825 Disabled Disabled 31741 k8s:app.kubernetes.io/name=hubble-relay fd02::1a9 10.0.1.94 ready
k8s:app.kubernetes.io/part-of=cilium
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=hubble-relay
k8s:io.kubernetes.pod.namespace=kube-system
k8s:k8s-app=hubble-relay
2299 Disabled Disabled 22165 k8s:io.cilium.k8s.policy.cluster=default fd02::188 10.0.1.95 ready
k8s:io.cilium.k8s.policy.serviceaccount=coredns
k8s:io.kubernetes.pod.namespace=kube-system
k8s:k8s-app=kube-dns
Stderr:
cmd: kubectl exec -n kube-system cilium-f9tbx -c cilium-agent -- cilium endpoint list
Exitcode: 0
Stdout:
ENDPOINT POLICY (ingress) POLICY (egress) IDENTITY LABELS (source:key[=value]) IPv6 IPv4 STATUS
ENFORCEMENT ENFORCEMENT
217 Disabled Disabled 56421 k8s:id=app1 fd02::b3 10.0.0.106 ready
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=app1-account
k8s:io.kubernetes.pod.namespace=202301101416k8sagenthubbletesthubbleobservetestl3l4flow
k8s:zgroup=testapp
550 Disabled Disabled 1 k8s:cilium.io/ci-node=k8s1 ready
k8s:node-role.kubernetes.io/control-plane
k8s:node-role.kubernetes.io/master
reserved:host
1643 Disabled Disabled 4 reserved:health fd02::5 10.0.0.97 ready
2886 Disabled Disabled 9139 k8s:appSecond=true fd02::b 10.0.0.254 ready
k8s:id=app2
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=app2-account
k8s:io.kubernetes.pod.namespace=202301101416k8sagenthubbletesthubbleobservetestl3l4flow
k8s:zgroup=testapp
3697 Disabled Disabled 56421 k8s:id=app1 fd02::f5 10.0.0.96 ready
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=app1-account
k8s:io.kubernetes.pod.namespace=202301101416k8sagenthubbletesthubbleobservetestl3l4flow
k8s:zgroup=testapp
3753 Disabled Disabled 22017 k8s:id=app3 fd02::d4 10.0.0.56 ready
k8s:io.cilium.k8s.policy.cluster=default
k8s:io.cilium.k8s.policy.serviceaccount=default
k8s:io.kubernetes.pod.namespace=202301101416k8sagenthubbletesthubbleobservetestl3l4flow
k8s:zgroup=testapp
Stderr:
===================== Exiting AfterFailed =====================
14:16:57 STEP: Running AfterEach for block EntireTestsuiteResources
This is happening in several pipelines of the CI. Here are some examples:
- https://jenkins.cilium.io/job/cilium-master-k8s-1.20-kernel-4.9/1706/testReport/junit/Suite-k8s-1/20/K8sAgentHubbleTest_Hubble_Observe_Test_L3_L4_Flow/
- https://jenkins.cilium.io/job/cilium-master-k8s-1.21-kernel-4.9/411/testReport/junit/Suite-k8s-1/21/K8sAgentIstioTest_Istio_Bookinfo_Demo_Tests_bookinfo_inter_service_connectivity/
Anything else?
This may be related to #17981, which was closed but is actually still happening. Not sure.