search

rancher / k3os

Purpose-built OS for Kubernetes, fully managed by Kubernetes.
https://k3os.io
Apache License 2.0
3.5k stars 397 forks source link

Go runtime: Observed a panic #330

Open David-Igou opened 4 years ago

David-Igou commented 4 years ago

Version

v0.8.0-rc3

Architecture

x86_64 AWS t2.Micro (unschedulable)

Describe the bug

API started to time out, Single masters response times became very slow. CloudWatch metrics doesn't show high CPU/memory usage?

To Reproduce

Happened overnight, no known stimulus to get same response

Expected/Actual behavior

Description of bug happened

Additional context

An alert was generated ~12:40

Trace[1132178515]: [559.296572ms] [559.223685ms] About to store object in database
Trace[1132178515]: [691.787931ms] [132.491359ms] Object stored in database
I1219 12:40:50.946403    1843 trace.go:116] Trace[1427583454]: "Create" url:/apis/authentication.k8s.io/v1beta1/tokenreviews (started: 2019-12-19 12:40:49.787089056 +0000 UTC m=+56009.072213103) (total time: 839.025791ms):
Trace[1427583454]: [359.327625ms] [350.601189ms] About to store object in database
Trace[1427583454]: [838.966673ms] [479.639048ms] Object stored in database
I1219 12:40:51.715807    1843 trace.go:116] Trace[182863516]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election (started: 2019-12-19 12:40:51.177049447 +0000 UTC m=+56010.462173418) (total time: 538.729035ms):
Trace[182863516]: [538.650697ms] [538.642418ms] About to write a response
I1219 12:40:51.756166    1843 trace.go:116] Trace[1126042523]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-controller (started: 2019-12-19 12:40:50.946314766 +0000 UTC m=+56010.231438733) (total time: 809.823799ms):
Trace[1126042523]: [809.749617ms] [809.735973ms] About to write a response
I1219 12:40:52.005870    1843 trace.go:116] Trace[744385522]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:40:51.176741996 +0000 UTC m=+56010.461865980) (total time: 829.079685ms):
Trace[744385522]: [829.006117ms] [828.993898ms] About to write a response
I1219 12:40:52.097256    1843 trace.go:116] Trace[1198642347]: "Get" url:/api/v1/namespaces/default (started: 2019-12-19 12:40:51.436012605 +0000 UTC m=+56010.721136572) (total time: 661.215831ms):
Trace[1198642347]: [661.165395ms] [661.151345ms] About to write a response
I1219 12:40:52.696075    1843 trace.go:116] Trace[939691258]: "GuaranteedUpdate etcd3" type:*core.ConfigMap (started: 2019-12-19 12:40:51.857453273 +0000 UTC m=+56011.142577308) (total time: 838.589409ms):
Trace[939691258]: [240.511047ms] [240.497332ms] Transaction prepared
Trace[939691258]: [838.554164ms] [598.043117ms] Transaction committed
I1219 12:40:52.696209    1843 trace.go:116] Trace[1017444041]: "Update" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-controller (started: 2019-12-19 12:40:51.857364134 +0000 UTC m=+56011.142488103) (total time: 838.830691ms):
Trace[1017444041]: [838.758531ms] [838.694502ms] Object stored in database
I1219 12:40:52.795882    1843 trace.go:116] Trace[566215185]: "GuaranteedUpdate etcd3" type:*core.ConfigMap (started: 2019-12-19 12:40:51.856289809 +0000 UTC m=+56011.141413831) (total time: 939.558149ms):
Trace[566215185]: [939.519505ms] [939.298553ms] Transaction committed
I1219 12:40:52.795997    1843 trace.go:116] Trace[1448873913]: "Update" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election (started: 2019-12-19 12:40:51.855982745 +0000 UTC m=+56011.141106719) (total time: 940.000037ms):
Trace[1448873913]: [939.928843ms] [939.662097ms] Object stored in database
I1219 12:40:53.056535    1843 trace.go:116] Trace[1907806415]: "GuaranteedUpdate etcd3" type:*core.ConfigMap (started: 2019-12-19 12:40:52.297503958 +0000 UTC m=+56011.582627980) (total time: 759.001268ms):
Trace[1907806415]: [758.988413ms] [758.769899ms] Transaction committed
I1219 12:40:53.056648    1843 trace.go:116] Trace[436245042]: "Update" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:40:52.297349193 +0000 UTC m=+56011.582473162) (total time: 759.284427ms):
Trace[436245042]: [759.214525ms] [759.09546ms] Object stored in database
I1219 12:40:53.376792    1843 trace.go:116] Trace[1665247616]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:40:52.366815719 +0000 UTC m=+56011.651939744) (total time: 1.009953114s):
Trace[1665247616]: [1.00992665s] [1.009120246s] Transaction committed
I1219 12:40:53.376879    1843 trace.go:116] Trace[659098335]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:40:52.366683884 +0000 UTC m=+56011.651807849) (total time: 1.010181676s):
Trace[659098335]: [1.01013537s] [1.010041269s] Object stored in database
I1219 12:40:53.905982    1843 trace.go:116] Trace[2001375137]: "Get" url:/api/v1/namespaces/default/services/kubernetes (started: 2019-12-19 12:40:52.93647442 +0000 UTC m=+56012.221598388) (total time: 969.472658ms):
Trace[2001375137]: [969.391901ms] [969.378907ms] About to write a response
I1219 12:40:59.046255    1843 trace.go:116] Trace[1905562295]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:40:55.658211557 +0000 UTC m=+56014.943335562) (total time: 3.388009021s):
Trace[1905562295]: [3.387964573s] [3.38773566s] Transaction committed
I1219 12:40:59.046372    1843 trace.go:116] Trace[1210338055]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-63.us-east-2.compute.internal (started: 2019-12-19 12:40:55.658078949 +0000 UTC m=+56014.943202915) (total time: 3.388277458s):
Trace[1210338055]: [3.388210626s] [3.388119683s] Object stored in database
I1219 12:40:59.046665    1843 trace.go:116] Trace[52649613]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:40:55.736593947 +0000 UTC m=+56015.021717925) (total time: 3.31005625s):
Trace[52649613]: [3.309997691s] [3.309986153s] About to write a response
I1219 12:41:03.356124    1843 trace.go:116] Trace[388005743]: "Get" url:/api/v1/nodes/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:02.118423952 +0000 UTC m=+56021.403547921) (total time: 1.23765636s):
Trace[388005743]: [1.237651754s] [1.237603956s] Transformed response object
I1219 12:41:05.456167    1843 trace.go:116] Trace[645296400]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:02.117630989 +0000 UTC m=+56021.402755026) (total time: 3.338504825s):
Trace[645296400]: [3.338469505s] [3.338327529s] Transaction committed
I1219 12:41:06.457181    1843 trace.go:116] Trace[1865553445]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:04.808965472 +0000 UTC m=+56024.094089438) (total time: 1.648162509s):
Trace[1865553445]: [1.647777887s] [1.647745661s] Conversion done
I1219 12:41:06.526468    1843 trace.go:116] Trace[299892431]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:02.556624378 +0000 UTC m=+56021.841748344) (total time: 3.969813502s):
Trace[299892431]: [2.55938858s] [2.559348976s] Conversion done
Trace[299892431]: [3.969739703s] [1.41023484s] Object stored in database
I1219 12:41:06.526879    1843 trace.go:116] Trace[314536184]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:02.117540791 +0000 UTC m=+56021.402664762) (total time: 4.409314629s):
Trace[314536184]: [3.338669391s] [3.338605866s] Object stored in database
Trace[314536184]: [4.409314629s] [1.070645238s] END
I1219 12:41:06.807858    1843 trace.go:116] Trace[1418007189]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election (started: 2019-12-19 12:40:55.659953142 +0000 UTC m=+56014.945077111) (total time: 11.147881011s):
Trace[1418007189]: [11.147819133s] [11.147810116s] About to write a response
I1219 12:41:06.944347    1843 trace.go:116] Trace[1479126439]: "List etcd3" key:/jobs,resourceVersion:,limit:500,continue: (started: 2019-12-19 12:40:52.875922921 +0000 UTC m=+56012.161046898) (total time: 14.068389561s):
Trace[1479126439]: [14.068389561s] [14.068389561s] END
I1219 12:41:08.016568    1843 trace.go:116] Trace[1663502288]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:02.266598002 +0000 UTC m=+56021.551722026) (total time: 5.749930901s):
Trace[1663502288]: [5.749883289s] [5.749665852s] Transaction committed
I1219 12:41:08.016678    1843 trace.go:116] Trace[699149635]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:02.266457099 +0000 UTC m=+56021.551581065) (total time: 5.750206596s):
Trace[699149635]: [5.750142735s] [5.750042572s] Object stored in database
I1219 12:41:09.516593    1843 trace.go:116] Trace[1950362109]: "GuaranteedUpdate etcd3" type:*core.ConfigMap (started: 2019-12-19 12:41:02.11652266 +0000 UTC m=+56021.401646678) (total time: 7.40004026s):
Trace[1950362109]: [7.40004026s] [7.399781547s] END
I1219 12:41:10.006340    1843 trace.go:116] Trace[733458963]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:04.506876104 +0000 UTC m=+56023.792000122) (total time: 5.499429029s):
Trace[733458963]: [5.499412812s] [5.499205574s] Transaction committed
I1219 12:41:10.006451    1843 trace.go:116] Trace[321868183]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:04.506737109 +0000 UTC m=+56023.791861077) (total time: 5.499698795s):
Trace[321868183]: [5.499637566s] [5.499538416s] Object stored in database
I1219 12:41:10.726177    1843 log.go:172] http: TLS handshake error from 10.1.1.189:50668: EOF
E1219 12:41:13.956479    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
E1219 12:41:12.616179    1843 resource_quota_controller.go:407] unable to retrieve the complete list of server APIs: metrics.k8s.io/v1beta1: the server is currently unable to handle the request
I1219 12:41:17.557093    1843 trace.go:116] Trace[2131712813]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-controller (started: 2019-12-19 12:41:09.016511224 +0000 UTC m=+56028.301635191) (total time: 8.540552063s):
Trace[2131712813]: [8.540468349s] [8.540456607s] About to write a response
I1219 12:41:18.419181    1843 trace.go:116] Trace[1416706386]: "Update" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:41:02.116346552 +0000 UTC m=+56021.401470521) (total time: 16.302805068s):
Trace[1416706386]: [16.302805068s] [16.302670599s] END
I1219 12:41:19.207311    1843 trace.go:116] Trace[1741982759]: "Patch" url:/api/v1/nodes/ip-10-1-1-11.us-east-2.compute.internal/status (started: 2019-12-19 12:41:07.917586256 +0000 UTC m=+56027.202710232) (total time: 11.289698922s):
Trace[1741982759]: [1.77966531s] [1.779610519s] About to apply patch
Trace[1741982759]: [11.289698922s] [9.510033612s] END
I1219 12:41:19.406638    1843 trace.go:116] Trace[1398375738]: "List etcd3" key:/minions,resourceVersion:,limit:0,continue: (started: 2019-12-19 12:41:08.966169246 +0000 UTC m=+56028.251293451) (total time: 10.440433683s):
Trace[1398375738]: [10.440433683s] [10.440433683s] END
I1219 12:41:19.927990    1843 trace.go:116] Trace[90838056]: "List" url:/apis/batch/v1/jobs (started: 2019-12-19 12:40:52.71693256 +0000 UTC m=+56012.002056518) (total time: 27.211028547s):
Trace[90838056]: [14.227462728s] [14.227401177s] Listing from storage done
Trace[90838056]: [27.211025482s] [12.983562754s] Writing http response done count:9
I1219 12:41:20.057694    1843 trace.go:116] Trace[1058891767]: "Patch" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal/status (started: 2019-12-19 12:41:06.056480887 +0000 UTC m=+56025.341604859) (total time: 14.001182334s):
Trace[1058891767]: [679.954821ms] [679.954821ms] Recorded the audit event
Trace[1058891767]: [3.490579659s] [2.810624838s] About to apply patch
Trace[1058891767]: [14.001182334s] [10.510602675s] END
I1219 12:41:21.117143    1843 trace.go:116] Trace[680238913]: "List" url:/api/v1/nodes (started: 2019-12-19 12:41:07.536490973 +0000 UTC m=+56026.821614947) (total time: 13.580616578s):
Trace[680238913]: [11.870187216s] [11.870173058s] Listing from storage done
Trace[680238913]: [13.580612632s] [1.710425416s] Writing http response done count:4
I1219 12:41:23.887340    1843 trace.go:116] Trace[1530162336]: "GuaranteedUpdate etcd3" type:*core.Event (started: 2019-12-19 12:41:12.696281536 +0000 UTC m=+56031.981405829) (total time: 11.191031089s):
Trace[1530162336]: [11.191015949s] [11.191015949s] initial value restored
I1219 12:41:23.887458    1843 trace.go:116] Trace[2030489391]: "Patch" url:/api/v1/namespaces/cert-manager/events/cert-manager-cainjector-6659d6844d-qm8bl.15e19227d2ea829e (started: 2019-12-19 12:41:08.047362551 +0000 UTC m=+56027.332486518) (total time: 15.840081059s):
Trace[2030489391]: [15.83993914s] [15.839908727s] About to apply patch
I1219 12:41:25.220218    1843 trace.go:116] Trace[2060730746]: "cacher list" type:*core.Secret (started: 2019-12-19 12:41:22.637381128 +0000 UTC m=+56041.922505104) (total time: 2.58279904s):
Trace[2060730746]: [2.582698078s] [2.582696276s] watchCache locked acquired
I1219 12:41:25.576844    1843 trace.go:116] Trace[1387998271]: "cacher list" type:*apiextensions.CustomResourceDefinition (started: 2019-12-19 12:41:22.848275372 +0000 UTC m=+56042.133399331) (total time: 2.728534384s):
Trace[1387998271]: [2.72849083s] [2.728489031s] watchCache locked acquired
I1219 12:41:25.947081    1843 trace.go:116] Trace[1410692345]: "Create" url:/apis/authentication.k8s.io/v1beta1/tokenreviews (started: 2019-12-19 12:41:23.357268764 +0000 UTC m=+56042.642392744) (total time: 2.58977181s):
Trace[1410692345]: [2.589655754s] [2.589437613s] Object stored in database
I1219 12:41:26.107023    1843 trace.go:116] Trace[1246647231]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:19.548155438 +0000 UTC m=+56038.833279464) (total time: 6.558835145s):
Trace[1246647231]: [6.558791353s] [6.558588494s] Transaction committed
I1219 12:41:26.107147    1843 trace.go:116] Trace[851630762]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:19.547993054 +0000 UTC m=+56038.833117022) (total time: 6.55914006s):
Trace[851630762]: [6.559074222s] [6.558950893s] Object stored in database
I1219 12:41:27.087200    1843 trace.go:116] Trace[1277261022]: "Get" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:18.399368601 +0000 UTC m=+56037.684492570) (total time: 8.687786059s):
Trace[1277261022]: [8.687655803s] [8.687615247s] About to write a response
I1219 12:41:27.947487    1843 trace.go:116] Trace[747595843]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:17.268830062 +0000 UTC m=+56036.553954085) (total time: 10.678627709s):
Trace[747595843]: [10.678627709s] [10.678383448s] END
I1219 12:41:28.087360    1843 trace.go:116] Trace[2059925786]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:19.797412495 +0000 UTC m=+56039.082547952) (total time: 8.289900144s):
Trace[2059925786]: [8.289900144s] [8.28967944s] END
I1219 12:41:28.267586    1843 trace.go:116] Trace[1772691430]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:20.035866395 +0000 UTC m=+56039.320990423) (total time: 8.231685315s):
Trace[1772691430]: [8.231647616s] [8.231427824s] Transaction committed
I1219 12:41:28.267690    1843 trace.go:116] Trace[406457698]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:20.035716316 +0000 UTC m=+56039.320840285) (total time: 8.231959483s):
Trace[406457698]: [8.231899243s] [8.231789249s] Object stored in database
I1219 12:41:29.187499    1843 trace.go:116] Trace[661038003]: "cacher list" type:*unstructured.Unstructured (started: 2019-12-19 12:41:25.327363865 +0000 UTC m=+56044.612487854) (total time: 3.860099308s):
Trace[661038003]: [3.860099308s] [3.860068409s] END
I1219 12:41:29.597173    1843 trace.go:116] Trace[615222688]: "Get" url:/api/v1/namespaces/monitoring/persistentvolumeclaims/prometheus-prometheus-db-prometheus-prometheus-0 (started: 2019-12-19 12:41:18.697243281 +0000 UTC m=+56037.982367249) (total time: 10.899894677s):
Trace[615222688]: [10.899819782s] [10.899806381s] About to write a response
I1219 12:41:32.627576    1843 trace.go:116] Trace[482131646]: "cacher list" type:*apiregistration.APIService (started: 2019-12-19 12:41:29.306838948 +0000 UTC m=+56048.591963174) (total time: 3.320697183s):
Trace[482131646]: [3.320644231s] [3.320640766s] watchCache locked acquired
E1219 12:41:33.087079    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:33.208140    1843 trace.go:116] Trace[1551308501]: "GuaranteedUpdate etcd3" type:*core.ConfigMap (started: 2019-12-19 12:41:19.657269105 +0000 UTC m=+56038.942393109) (total time: 13.550844299s):
Trace[1551308501]: [13.550805256s] [13.550590071s] Transaction committed
I1219 12:41:33.208250    1843 trace.go:116] Trace[2069425675]: "Update" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-controller (started: 2019-12-19 12:41:19.657129856 +0000 UTC m=+56038.942253825) (total time: 13.551105983s):
Trace[2069425675]: [13.55104107s] [13.550938508s] Object stored in database
I1219 12:41:31.296923    1843 trace.go:116] Trace[1505174144]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-63.us-east-2.compute.internal (started: 2019-12-19 12:41:17.268672604 +0000 UTC m=+56036.553796568) (total time: 14.028218682s):
Trace[1505174144]: [14.028218682s] [14.028116155s] END
E1219 12:41:31.296944    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:34.019789    1843 trace.go:116] Trace[1925061823]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:19.797281339 +0000 UTC m=+56039.082405306) (total time: 14.222483739s):
Trace[1925061823]: [14.222483739s] [14.222388417s] END
I1219 12:41:31.970018    1843 trace.go:116] Trace[1354288204]: "GuaranteedUpdate etcd3" type:*core.Node (started: 2019-12-19 12:41:09.086715153 +0000 UTC m=+56028.371839162) (total time: 22.883264577s):
Trace[1354288204]: [460.340951ms] [460.340951ms] initial value restored
Trace[1354288204]: [22.883213459s] [22.422872508s] Transaction prepared
I1219 12:41:31.970170    1843 trace.go:116] Trace[1000880698]: "GuaranteedUpdate etcd3" type:*core.Node (started: 2019-12-19 12:41:09.697171048 +0000 UTC m=+56028.982295357) (total time: 22.272982778s):
Trace[1000880698]: [22.272949123s] [22.272872162s] Transaction prepared
I1219 12:41:31.058815    1843 controller.go:107] OpenAPI AggregationController: Processing item v1beta1.metrics.k8s.io
E1219 12:41:37.727324    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:37.727521    1843 trace.go:116] Trace[1316250696]: "Get" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:34.458423693 +0000 UTC m=+56053.743547661) (total time: 3.269073712s):
Trace[1316250696]: [3.269073712s] [3.269033046s] END
E1219 12:41:37.751584    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:37.751762    1843 trace.go:116] Trace[1088876357]: "Get" url:/api/v1/nodes/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:35.938411471 +0000 UTC m=+56055.223535439) (total time: 1.813330341s):
Trace[1088876357]: [1.813330341s] [1.81328945s] END
E1219 12:41:37.751966    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:35.037856    1843 trace.go:116] Trace[1485290966]: "List" url:/apis/cert-manager.io/v1alpha2/certificates (started: 2019-12-19 12:41:25.327241816 +0000 UTC m=+56044.612365792) (total time: 9.71054113s):
Trace[1485290966]: [6.949796208s] [6.949687394s] Listing from storage done
Trace[1485290966]: [9.710536627s] [2.760740419s] Writing http response done count:4
I1219 12:41:35.617118    1843 trace.go:116] Trace[1453911632]: "Get" url:/api/v1/nodes/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:20.368628296 +0000 UTC m=+56039.653752262) (total time: 15.248459627s):
Trace[1453911632]: [15.248459627s] [15.24842204s] END
E1219 12:41:36.347952    1843 controller.go:170] failed to update node lease, error: Put https://127.0.0.1:6443/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-63.us-east-2.compute.internal?timeout=10s: context deadline exceeded (Client.Timeout exceeded while awaiting headers)
I1219 12:41:36.997069    1843 trace.go:116] Trace[1416534226]: "List" url:/apis/admissionregistration.k8s.io/v1beta1/mutatingwebhookconfigurations (started: 2019-12-19 12:41:22.78701674 +0000 UTC m=+56042.072140717) (total time: 14.210017849s):
Trace[1416534226]: [2.679938209s] [2.679883022s] Listing from storage done
Trace[1416534226]: [14.210013879s] [11.53007567s] Writing http response done count:1
I1219 12:41:37.217978    1843 trace.go:116] Trace[526205372]: "List" url:/apis/apiregistration.k8s.io/v1beta1/apiservices (started: 2019-12-19 12:41:22.93691733 +0000 UTC m=+56042.222041300) (total time: 14.281022445s):
Trace[526205372]: [2.66014015s] [2.66014015s] About to List from storage
Trace[526205372]: [9.690684605s] [7.030544455s] Listing from storage done
Trace[526205372]: [14.28101858s] [4.590333975s] Writing http response done count:37
I1219 12:41:37.237373    1843 trace.go:116] Trace[489338177]: "List" url:/apis/admissionregistration.k8s.io/v1beta1/validatingwebhookconfigurations (started: 2019-12-19 12:41:23.116987181 +0000 UTC m=+56042.402111161) (total time: 14.120358902s):
Trace[489338177]: [2.619770308s] [2.619715447s] Listing from storage done
Trace[489338177]: [14.120355575s] [11.500585267s] Writing http response done count:1
I1219 12:41:37.237569    1843 trace.go:116] Trace[1602291755]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election (started: 2019-12-19 12:41:23.197047196 +0000 UTC m=+56042.482171165) (total time: 14.040507598s):
Trace[1602291755]: [14.040450181s] [14.040437642s] About to write a response
I1219 12:41:37.577279    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37226: EOF
I1219 12:41:37.848006    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37228: EOF
I1219 12:41:37.848033    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37232: EOF
I1219 12:41:37.848053    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37234: EOF
I1219 12:41:37.848070    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37236: EOF
I1219 12:41:37.848087    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37238: EOF
I1219 12:41:37.848104    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37240: EOF
I1219 12:41:37.848120    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37230: EOF
I1219 12:41:38.074323    1843 trace.go:116] Trace[1707650274]: "List" url:/api/v1/secrets (started: 2019-12-19 12:41:35.759774294 +0000 UTC m=+56055.044898256) (total time: 2.314510504s):
Trace[1707650274]: [2.314506392s] [2.314386561s] Writing http response done count:87
I1219 12:41:38.076127    1843 trace.go:116] Trace[447197684]: "List" url:/api/v1/nodes (started: 2019-12-19 12:41:37.488048238 +0000 UTC m=+56056.773172195) (total time: 588.05541ms):
Trace[447197684]: [587.86269ms] [587.800737ms] Listing from storage done
I1219 12:41:40.308425    1843 trace.go:116] Trace[834915968]: "cacher list" type:*storage.CSIDriver (started: 2019-12-19 12:41:38.128377912 +0000 UTC m=+56057.413501881) (total time: 2.180021948s):
Trace[834915968]: [2.180021948s] [2.179999909s] END
I1219 12:41:40.328131    1843 trace.go:116] Trace[1720525295]: "List" url:/api/v1/namespaces/logging/configmaps (started: 2019-12-19 12:41:38.168405032 +0000 UTC m=+56057.453529001) (total time: 2.159689998s):
Trace[1720525295]: [2.159686237s] [2.159592824s] Writing http response done count:1
I1219 12:41:40.377372    1843 trace.go:116] Trace[111937588]: "cacher list" type:*node.RuntimeClass (started: 2019-12-19 12:41:38.210633775 +0000 UTC m=+56057.495757747) (total time: 2.166700527s):
Trace[111937588]: [2.166700527s] [2.166687784s] END
I1219 12:41:40.377542    1843 trace.go:116] Trace[1915573468]: "List" url:/apis/node.k8s.io/v1beta1/runtimeclasses (started: 2019-12-19 12:41:38.210576824 +0000 UTC m=+56057.495700793) (total time: 2.166886891s):
Trace[1915573468]: [2.166818936s] [2.166768674s] Listing from storage done
E1219 12:41:40.524028    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:40.524214    1843 trace.go:116] Trace[1637841209]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:38.538033424 +0000 UTC m=+56057.823157391) (total time: 1.98615973s):
Trace[1637841209]: [1.98615973s] [1.986064111s] END
I1219 12:41:40.524611    1843 trace.go:116] Trace[1443690598]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:34.458969951 +0000 UTC m=+56053.744093922) (total time: 6.065623578s):
Trace[1443690598]: [4.125639229s] [4.125606752s] Conversion done
Trace[1443690598]: [6.065568994s] [1.939806601s] Object stored in database
E1219 12:41:40.657510    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:40.657703    1843 trace.go:116] Trace[757041008]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:38.777666792 +0000 UTC m=+56058.062790761) (total time: 1.880015414s):
Trace[757041008]: [1.880015414s] [1.879914869s] END
E1219 12:41:40.658201    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:40.713003    1843 trace.go:116] Trace[504741167]: "List" url:/api/v1/secrets (started: 2019-12-19 12:41:22.637312135 +0000 UTC m=+56041.922436105) (total time: 18.075665193s):
Trace[504741167]: [2.582938199s] [2.582880729s] Listing from storage done
Trace[504741167]: [18.075661283s] [15.492723084s] Writing http response done count:87
I1219 12:41:40.797762    1843 trace.go:116] Trace[2100613865]: "Get" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:38.098342759 +0000 UTC m=+56057.383466729) (total time: 2.699390407s):
Trace[2100613865]: [2.699237432s] [2.699209993s] About to write a response
E1219 12:41:41.018194    1843 status.go:71] apiserver received an error that is not an metav1.Status: context.deadlineExceededError{}
I1219 12:41:41.018517    1843 trace.go:116] Trace[1708602718]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:38.849343305 +0000 UTC m=+56058.134467274) (total time: 2.169152236s):
Trace[1708602718]: [2.169152236s] [2.169079332s] END
time="2019-12-19T12:41:39.209369190Z" level=error msg="error while range on /registry/minions/ip-10-1-1-11.us-east-2.compute.internal : context canceled"
time="2019-12-19T12:41:40.308036386Z" level=error msg="error while range on /registry/persistentvolumeclaims/monitoring/prometheus-prometheus-db-prometheus-prometheus-0 : context canceled"
I1219 12:41:41.118001    1843 trace.go:116] Trace[1049182060]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:39.627835315 +0000 UTC m=+56058.912959285) (total time: 1.490141356s):
Trace[1049182060]: [1.490059089s] [1.489867463s] Object stored in database
I1219 12:41:41.317839    1843 trace.go:116] Trace[722175]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:39.955916149 +0000 UTC m=+56059.241040117) (total time: 1.361891176s):
Trace[722175]: [1.361891176s] [1.36161241s] END
I1219 12:41:41.340283    1843 trace.go:116] Trace[1213260598]: "List" url:/api/v1/services (started: 2019-12-19 12:41:38.288223667 +0000 UTC m=+56057.573347615) (total time: 3.052024095s):
Trace[1213260598]: [3.052020768s] [3.051913198s] Writing http response done count:20
I1219 12:41:41.340461    1843 trace.go:116] Trace[1395865664]: "Get" url:/api/v1/namespaces/flux/secrets/flux-git-deploy (started: 2019-12-19 12:41:34.01852381 +0000 UTC m=+56053.303647774) (total time: 7.321923616s):
Trace[1395865664]: [7.32185676s] [7.321848414s] About to write a response
I1219 12:41:41.647772    1843 trace.go:116] Trace[588688858]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:41:35.818315391 +0000 UTC m=+56055.103439348) (total time: 5.829427661s):
Trace[588688858]: [5.829343568s] [5.829335248s] About to write a response
I1219 12:41:41.849697    1843 trace.go:116] Trace[501716403]: "Create" url:/api/v1/namespaces/kube-system/events (started: 2019-12-19 12:41:10.488086063 +0000 UTC m=+56029.773210020) (total time: 31.361585905s):
Trace[501716403]: [3.608469005s] [3.608430581s] Conversion done
Trace[501716403]: [7.931446618s] [4.322977613s] About to store object in database
Trace[501716403]: [31.361585905s] [23.430139287s] END
I1219 12:41:41.862146    1843 trace.go:116] Trace[1904626065]: "List" url:/api/v1/services (started: 2019-12-19 12:41:39.474970037 +0000 UTC m=+56058.760094005) (total time: 2.387138701s):
Trace[1904626065]: [2.387135624s] [2.387045212s] Writing http response done count:20
I1219 12:41:41.907659    1843 trace.go:116] Trace[1847911159]: "List" url:/apis/storage.k8s.io/v1beta1/csidrivers (started: 2019-12-19 12:41:39.513423262 +0000 UTC m=+56058.798547230) (total time: 2.394202784s):
Trace[1847911159]: [2.394198859s] [2.394120456s] Writing http response done count:1
I1219 12:41:41.957267    1843 trace.go:116] Trace[1340064836]: "Get" url:/api/v1/namespaces/cert-manager/pods/cert-manager-cainjector-6659d6844d-qm8bl (started: 2019-12-19 12:41:06.887283653 +0000 UTC m=+56026.172407621) (total time: 35.069945123s):
Trace[1340064836]: [30.370277005s] [30.370264791s] About to write a response
Trace[1340064836]: [35.069941214s] [4.699664209s] Transformed response object
E1219 12:41:41.957445    1843 goroutinemap.go:150] Operation for "/var/lib/kubelet/plugins/ebs.csi.aws.com/csi.sock" failed. No retries permitted until 2019-12-19 12:43:41.707180666 +0000 UTC m=+56180.992305972 (durationBeforeRetry 2m2s). Error: "RegisterPlugin error -- dial failed at socket /var/lib/kubelet/plugins/ebs.csi.aws.com/csi.sock, err: failed to dial socket /var/lib/kubelet/plugins/ebs.csi.aws.com/csi.sock, err: context deadline exceeded"
I1219 12:41:42.119274    1843 trace.go:116] Trace[46588850]: "List" url:/apis/storage.k8s.io/v1beta1/csidrivers (started: 2019-12-19 12:41:38.128318074 +0000 UTC m=+56057.413442046) (total time: 3.990913888s):
Trace[46588850]: [2.18013149s] [2.180079369s] Listing from storage done
Trace[46588850]: [3.990910283s] [1.810778793s] Writing http response done count:1
I1219 12:41:42.120534    1843 trace.go:116] Trace[954489081]: "GuaranteedUpdate etcd3" type:*v1.Endpoints (started: 2019-12-19 12:40:54.315609822 +0000 UTC m=+56013.600733988) (total time: 47.804898883s):
Trace[954489081]: [2.5805556s] [2.5805556s] initial value restored
Trace[954489081]: [17.287780131s] [14.707224531s] Transaction prepared
Trace[954489081]: [25.232977967s] [7.945197836s] Transaction committed
Trace[954489081]: [37.111652918s] [11.878669736s] Transaction prepared
Trace[954489081]: [46.141702615s] [9.030049697s] Transaction committed
Trace[954489081]: [47.804898883s] [1.663196268s] END
I1219 12:41:42.796808    1843 trace.go:116] Trace[1507276431]: "List" url:/apis/apiextensions.k8s.io/v1beta1/customresourcedefinitions (started: 2019-12-19 12:41:35.727838387 +0000 UTC m=+56055.012962350) (total time: 7.068935913s):
Trace[1507276431]: [7.068932019s] [7.068798976s] Writing http response done count:16
I1219 12:41:44.405177    1843 trace.go:116] Trace[875031866]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:40.308146103 +0000 UTC m=+56059.593270114) (total time: 4.097010447s):
Trace[875031866]: [4.097010447s] [4.096973811s] END
E1219 12:41:46.038919    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:46.039100    1843 trace.go:116] Trace[1102037358]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:38.100662973 +0000 UTC m=+56057.385786935) (total time: 7.938416662s):
Trace[1102037358]: [2.207435804s] [2.207354797s] About to store object in database
Trace[1102037358]: [7.938416662s] [5.730980858s] END
I1219 12:41:44.587894    1843 trace.go:116] Trace[805755654]: "Create" url:/apis/authorization.k8s.io/v1beta1/subjectaccessreviews (started: 2019-12-19 12:41:41.863086683 +0000 UTC m=+56061.148210650) (total time: 2.72478019s):
Trace[805755654]: [2.724465951s] [2.72443287s] Conversion done
I1219 12:41:52.562478    1843 trace.go:116] Trace[388382935]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:40.329089661 +0000 UTC m=+56059.614213699) (total time: 12.233354597s):
Trace[388382935]: [1.010144877s] [1.010126199s] Transaction prepared
Trace[388382935]: [10.019152589s] [9.009007712s] Transaction committed
Trace[388382935]: [12.233354597s] [2.214202008s] END
I1219 12:41:45.028254    1843 trace.go:116] Trace[1154888823]: "List" url:/apis/apiextensions.k8s.io/v1beta1/customresourcedefinitions (started: 2019-12-19 12:41:22.848213071 +0000 UTC m=+56042.133337028) (total time: 22.179970412s):
Trace[1154888823]: [2.728666138s] [2.72861199s] Listing from storage done
Trace[1154888823]: [22.179966014s] [19.451299876s] Writing http response done count:16
I1219 12:41:58.878492    1843 trace.go:116] Trace[1664150291]: "Create" url:/apis/authentication.k8s.io/v1beta1/tokenreviews (started: 2019-12-19 12:41:51.358077326 +0000 UTC m=+56070.643201295) (total time: 7.520386659s):
Trace[1664150291]: [7.520297194s] [7.520079413s] Object stored in database
I1219 12:41:59.888143    1843 trace.go:116] Trace[1390565944]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:39.332491035 +0000 UTC m=+56058.617615005) (total time: 20.555622521s):
Trace[1390565944]: [20.555622521s] [20.555547327s] END
I1219 12:42:00.089205    1843 trace.go:116] Trace[250485965]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election-core (started: 2019-12-19 12:41:46.428939284 +0000 UTC m=+56065.714063248) (total time: 13.660237092s):
Trace[250485965]: [13.660166293s] [13.66015477s] About to write a response
I1219 12:42:00.089654    1843 trace.go:116] Trace[1833582499]: "Get" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:45.933013031 +0000 UTC m=+56065.218136996) (total time: 14.156609287s):
Trace[1833582499]: [14.156483503s] [14.156455644s] About to write a response
I1219 12:42:01.179535    1843 trace.go:116] Trace[1636426332]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:46.038639098 +0000 UTC m=+56065.323763079) (total time: 15.140848053s):
Trace[1636426332]: [15.140848053s] [15.140798996s] END
E1219 12:42:01.878102    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:41:45.477943    1843 trace.go:116] Trace[198015707]: "Create" url:/api/v1/namespaces/cert-manager/events (started: 2019-12-19 12:41:26.214303241 +0000 UTC m=+56045.499427189) (total time: 19.263609473s):
Trace[198015707]: [19.263521911s] [19.263321968s] Object stored in database
I1219 12:41:45.587641    1843 trace.go:116] Trace[157340590]: "Get" url:/api/v1/namespaces/kube-system/configmaps/cert-manager-cainjector-leader-election (started: 2019-12-19 12:41:41.387891276 +0000 UTC m=+56060.673015248) (total time: 4.199720865s):
Trace[157340590]: [4.199640055s] [4.19962814s] About to write a response
I1219 12:41:45.587910    1843 trace.go:116] Trace[2131099974]: "Get" url:/api/v1/nodes/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:39.330485031 +0000 UTC m=+56058.615609000) (total time: 6.257408778s):
Trace[2131099974]: [6.257273304s] [6.257235868s] About to write a response
I1219 12:41:45.927564    1843 trace.go:116] Trace[749331731]: "Get" url:/api/v1/namespaces/monitoring/persistentvolumeclaims/prometheus-prometheus-db-prometheus-prometheus-0 (started: 2019-12-19 12:41:39.453958812 +0000 UTC m=+56058.739082775) (total time: 6.473568421s):
Trace[749331731]: [6.473489283s] [6.473481395s] About to write a response
I1219 12:41:50.348214    1843 trace.go:116] Trace[1434868175]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:39.332599933 +0000 UTC m=+56058.617723961) (total time: 11.015578069s):
Trace[1434868175]: [1.735007309s] [1.734985697s] Transaction prepared
Trace[1434868175]: [11.015525846s] [9.280518537s] Transaction committed
I1219 12:41:50.838191    1843 trace.go:116] Trace[232842250]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:42.148249385 +0000 UTC m=+56061.433373402) (total time: 8.689911529s):
Trace[232842250]: [8.689911529s] [8.689886783s] END
I1219 12:41:51.828528    1843 trace.go:116] Trace[1804146608]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:40.328976588 +0000 UTC m=+56059.614100565) (total time: 11.499525918s):
Trace[1804146608]: [11.499525918s] [11.49944484s] END
I1219 12:41:56.827919    1843 trace.go:116] Trace[1677619087]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-63.us-east-2.compute.internal (started: 2019-12-19 12:41:42.148121619 +0000 UTC m=+56061.433245586) (total time: 14.679768808s):
Trace[1677619087]: [14.679768808s] [14.679676168s] END
I1219 12:41:56.938160    1843 trace.go:116] Trace[146595242]: "Patch" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal/status (started: 2019-12-19 12:41:42.517567464 +0000 UTC m=+56061.802691436) (total time: 14.420540444s):
Trace[146595242]: [2.890317971s] [2.890237984s] About to apply patch
Trace[146595242]: [14.420540444s] [11.530222473s] END
I1219 12:42:02.259771    1843 trace.go:116] Trace[1259385487]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:52.222774202 +0000 UTC m=+56071.507898169) (total time: 10.036971506s):
Trace[1259385487]: [10.036971506s] [10.036898958s] END
I1219 12:42:03.279126    1843 trace.go:116] Trace[820917844]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:52.222881162 +0000 UTC m=+56071.508005159) (total time: 11.056201386s):
Trace[820917844]: [11.056201386s] [11.056174483s] END
E1219 12:42:03.887945    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:42:03.888186    1843 trace.go:116] Trace[662721727]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:41:46.038499646 +0000 UTC m=+56065.323623595) (total time: 17.849663451s):
Trace[662721727]: [17.849663451s] [17.84955835s] END
I1219 12:42:04.099399    1843 trace.go:116] Trace[1696509416]: "Get" url:/api/v1/nodes/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:58.309672006 +0000 UTC m=+56077.594795977) (total time: 5.789698998s):
Trace[1696509416]: [5.789698998s] [5.789648099s] END
I1219 12:42:04.533386    1843 trace.go:116] Trace[117504244]: "Patch" url:/api/v1/nodes/ip-10-1-1-189.us-east-2.compute.internal/status (started: 2019-12-19 12:41:45.828643048 +0000 UTC m=+56065.113766988) (total time: 18.704714555s):
Trace[117504244]: [18.704714555s] [18.70447963s] END
E1219 12:42:04.579454    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:42:04.579650    1843 trace.go:116] Trace[1837203495]: "Get" url:/api/v1/namespaces/monitoring/persistentvolumeclaims/prometheus-prometheus-db-prometheus-prometheus-0 (started: 2019-12-19 12:41:52.223908489 +0000 UTC m=+56071.509032458) (total time: 12.355719828s):
Trace[1837203495]: [12.355719828s] [12.355712076s] END
E1219 12:42:04.580322    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:42:05.968057    1843 trace.go:116] Trace[444167773]: "GuaranteedUpdate etcd3" type:*coordination.Lease (started: 2019-12-19 12:41:54.198759442 +0000 UTC m=+56073.483883469) (total time: 11.769262404s):
Trace[444167773]: [11.769262404s] [11.769237165s] END
E1219 12:42:05.968107    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
E1219 12:42:07.139288    1843 controller.go:170] failed to update node lease, error: Put https://127.0.0.1:6443/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-63.us-east-2.compute.internal?timeout=10s: context deadline exceeded (Client.Timeout exceeded while awaiting headers)
time="2019-12-19T12:42:06.704304148Z" level=error msg="error while range on /registry/minions/ip-10-1-1-189.us-east-2.compute.internal : context canceled"
time="2019-12-19T12:42:09.958461136Z" level=error msg="error while range on /registry/leases/kube-node-lease/ip-10-1-1-11.us-east-2.compute.internal : context canceled"
I1219 12:42:11.088536    1843 trace.go:116] Trace[585381182]: "Get" url:/api/v1/nodes/ip-10-1-1-11.us-east-2.compute.internal (started: 2019-12-19 12:41:52.209970934 +0000 UTC m=+56071.495094898) (total time: 18.87853651s):
Trace[585381182]: [18.87853651s] [18.878509264s] END
I1219 12:42:11.209134    1843 trace.go:116] Trace[215374917]: "Update" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-189.us-east-2.compute.internal (started: 2019-12-19 12:41:54.19863386 +0000 UTC m=+56073.483757826) (total time: 17.010474503s):
Trace[215374917]: [17.010474503s] [17.010385829s] END
time="2019-12-19T12:42:12.158678957Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"
time="2019-12-19T12:42:12.748798088Z" level=error msg="error while range on /registry/minions/ip-10-1-1-11.us-east-2.compute.internal : context canceled"
I1219 12:42:21.678498    1843 log.go:172] http: TLS handshake error from 10.1.1.11:1087: EOF
I1219 12:42:42.220572    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37366: EOF
I1219 12:42:50.109394    1843 trace.go:116] Trace[103962145]: "cacher list" type:*core.Node (started: 2019-12-19 12:42:13.150568867 +0000 UTC m=+56092.435692839) (total time: 9.868021896s):
Trace[103962145]: [9.867990955s] [9.867988193s] watchCache locked acquired
E1219 12:41:53.718572    1843 event.go:256] Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"ebs-csi-node-5bdvf.15e1c6328c0355c2", GenerateName:"", Namespace:"kube-system", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Finalizers:[]string(nil), ClusterName:"", ManagedFields:[]v1.ManagedFieldsEntry(nil)}, InvolvedObject:v1.ObjectReference{Kind:"Pod", Namespace:"kube-system", Name:"ebs-csi-node-5bdvf", UID:"ae8b0b29-4028-4b67-bce8-77e6ff2f69a3", APIVersion:"v1", ResourceVersion:"365122", FieldPath:"spec.containers{ebs-plugin}"}, Reason:"Unhealthy", Message:"Liveness probe failed: HTTP probe failed with statuscode: 500", Source:v1.EventSource{Component:"kubelet", Host:"ip-10-1-1-63.us-east-2.compute.internal"}, FirstTimestamp:v1.Time{Time:time.Time{wall:0xbf76f9d838fc95c2, ext:56024241201474, loc:(*time.Location)(0x6c2d480)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0xbf76f9d838fc95c2, ext:56024241201474, loc:(*time.Location)(0x6c2d480)}}, Count:1, Type:"Warning", EventTime:v1.MicroTime{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, Series:(*v1.EventSeries)(nil), Action:"", Related:(*v1.ObjectReference)(nil), ReportingController:"", ReportingInstance:""}': 'context deadline exceeded' (will not retry!)
E1219 12:42:53.459487    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:42:53.670598    1843 trace.go:116] Trace[1459937766]: "iptables save" (started: 2019-12-19 12:42:10.348193106 +0000 UTC m=+56089.633317212) (total time: 19.940606575s):
Trace[1459937766]: [19.940606575s] [19.940606575s] END
W1219 12:42:20.068400    1843 garbagecollector.go:640] failed to discover some groups: map[metrics.k8s.io/v1beta1:the server is currently unable to handle the request]
I1219 12:42:55.870514    1843 log.go:172] http: TLS handshake error from 10.1.1.109:37368: EOF
time="2019-12-19T12:42:42.949286826Z" level=info msg="error in remotedialer server [400]: websocket: close 1006 (abnormal closure): unexpected EOF"
I1219 12:42:56.399782    1843 trace.go:116] Trace[534046932]: "List" url:/apis/node.k8s.io/v1beta1/runtimeclasses (started: 2019-12-19 12:42:13.190402235 +0000 UTC m=+56092.475526180) (total time: 43.209315258s):
Trace[534046932]: [9.998416571s] [9.998351569s] Listing from storage done
Trace[534046932]: [43.209310765s] [33.210894194s] Writing http response done count:0
I1219 12:43:03.849947    1843 trace.go:116] Trace[558620281]: "Get" url:/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:42:13.189368214 +0000 UTC m=+56092.474492180) (total time: 50.660524219s):
Trace[558620281]: [50.660524219s] [50.660482732s] END
E1219 12:43:04.040835    1843 status.go:71] apiserver received an error that is not an metav1.Status: &status.statusError{Code:14, Message:"transport is closing", Details:[]*any.Any(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}
I1219 12:43:07.282072    1843 trace.go:116] Trace[1831332930]: "List etcd3" key:/cronjobs,resourceVersion:,limit:500,continue: (started: 2019-12-19 12:42:11.678306366 +0000 UTC m=+56090.963430502) (total time: 43.11969211s):
Trace[1831332930]: [43.11969211s] [43.11969211s] END
E1219 12:43:21.701137    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
E1219 12:43:21.701221    1843 writers.go:105] apiserver was unable to write a JSON response: http: Handler timeout
E1219 12:43:08.829996    1843 writers.go:105] apiserver was unable to write a JSON response: http: Handler timeout
E1219 12:43:13.050379    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:43:13.050473    1843 trace.go:116] Trace[678909651]: "List etcd3" key:/minions,resourceVersion:,limit:0,continue: (started: 2019-12-19 12:42:12.858778485 +0000 UTC m=+56092.143902704) (total time: 1m0.191654482s):
Trace[678909651]: [1m0.191654482s] [1m0.191654482s] END
E1219 12:43:21.701277    1843 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"context canceled"}
I1219 12:43:21.280956    1843 trace.go:116] Trace[2028802001]: "Get" url:/api/v1/nodes/ip-10-1-1-109.us-east-2.compute.internal (started: 2019-12-19 12:42:15.549002115 +0000 UTC m=+56094.834126084) (total time: 1m5.731883504s):
Trace[2028802001]: [41.450889032s] [41.450889032s] About to Get from storage
Trace[2028802001]: [1m5.731646574s] [24.280757542s] About to write a response
E1219 12:43:21.790834    1843 reflector.go:280] object-"logging"/"loki-promtail-token-b6h44": Failed to watch *v1.Secret: Get https://127.0.0.1:6443/api/v1/namespaces/logging/secrets?allowWatchBookmarks=true&fieldSelector=metadata.name%3Dloki-promtail-token-b6h44&resourceVersion=435092&timeout=6m44s&timeoutSeconds=404&watch=true: net/http: TLS handshake timeout
E1219 12:43:21.790983    1843 reflector.go:280] object-"kube-system"/"default-token-tq74b": Failed to watch *v1.Secret: Get https://127.0.0.1:6443/api/v1/namespaces/kube-system/secrets?allowWatchBookmarks=true&fieldSelector=metadata.name%3Ddefault-token-tq74b&resourceVersion=435092&timeout=6m58s&timeoutSeconds=418&watch=true: net/http: TLS handshake timeout
E1219 12:43:21.791173    1843 reflector.go:280] k8s.io/kubernetes/pkg/kubelet/config/apiserver.go:46: Failed to watch *v1.Pod: Get https://127.0.0.1:6443/api/v1/pods?allowWatchBookmarks=true&fieldSelector=spec.nodeName%3Dip-10-1-1-63.us-east-2.compute.internal&resourceVersion=435102&timeoutSeconds=431&watch=true: net/http: TLS handshake timeout
E1219 12:43:22.340950    1843 reflector.go:280] object-"kube-system"/"eventrouter-cm": Failed to watch *v1.ConfigMap: Get https://127.0.0.1:6443/api/v1/namespaces/kube-system/configmaps?allowWatchBookmarks=true&fieldSelector=metadata.name%3Deventrouter-cm&resourceVersion=494180&timeout=8m36s&timeoutSeconds=516&watch=true: net/http: TLS handshake timeout
E1219 12:43:22.341154    1843 reflector.go:280] k8s.io/kubernetes/pkg/kubelet/kubelet.go:459: Failed to watch *v1.Node: Get https://127.0.0.1:6443/api/v1/nodes?allowWatchBookmarks=true&fieldSelector=metadata.name%3Dip-10-1-1-63.us-east-2.compute.internal&resourceVersion=494510&timeoutSeconds=498&watch=true: net/http: TLS handshake timeout
E1219 12:43:22.341312    1843 reflector.go:280] object-"monitoring"/"node-exporter-token-msjjh": Failed to watch *v1.Secret: Get https://127.0.0.1:6443/api/v1/namespaces/monitoring/secrets?allowWatchBookmarks=true&fieldSelector=metadata.name%3Dnode-exporter-token-msjjh&resourceVersion=435092&timeout=6m10s&timeoutSeconds=370&watch=true: net/http: TLS handshake timeout
E1219 12:43:22.470748    1843 reflector.go:280] object-"kube-system"/"coredns-token-s2shd": Failed to watch *v1.Secret: Get https://127.0.0.1:6443/api/v1/namespaces/kube-system/secrets?allowWatchBookmarks=true&fieldSelector=metadata.name%3Dcoredns-token-s2shd&resourceVersion=435092&timeout=7m12s&timeoutSeconds=432&watch=true: net/http: TLS handshake timeout
E1219 12:43:22.470855    1843 reflector.go:280] k8s.io/client-go/informers/factory.go:134: Failed to watch *v1beta1.RuntimeClass: Get https://127.0.0.1:6443/apis/node.k8s.io/v1beta1/runtimeclasses?allowWatchBookmarks=true&resourceVersion=403218&timeout=8m9s&timeoutSeconds=489&watch=true: dial tcp 127.0.0.1:6443: i/o timeout
E1219 12:43:21.320484    1843 resource_quota_controller.go:407] failed to discover resources: Get https://127.0.0.1:6444/api?timeout=32s: context deadline exceeded (Client.Timeout exceeded while awaiting headers)
I1219 12:43:21.700972    1843 trace.go:116] Trace[1213199777]: "Get" url:/api/v1/namespaces/kube-system (started: 2019-12-19 12:42:10.228489166 +0000 UTC m=+56089.513613135) (total time: 1m11.472451663s):
Trace[1213199777]: [1m11.472451663s] [1m11.472439061s] END
E1219 12:43:21.701053    1843 runtime.go:78] Observed a panic: &errors.errorString{s:"killing connection/stream because serving request timed out and response had been started"} (killing connection/stream because serving request timed out and response had been started)
goroutine 5820766 [running]:
github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/runtime.logPanic(0x373ebc0, 0xc0005b0170)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/runtime/runtime.go:74 +0xa3
github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/runtime.HandleCrash(0xc00357dc90, 0x1, 0x1)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apimachinery/pkg/util/runtime/runtime.go:48 +0x82
panic(0x373ebc0, 0xc0005b0170)
    /usr/local/go/src/runtime/panic.go:679 +0x1b2
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).timeout(0xc0039328e0, 0xc01b62edc0)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:257 +0x1cf
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP(0xc0094574a0, 0x46cdcc0, 0xc01692c5b0, 0xc00a6d1a00)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:141 +0x310
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.WithWaitGroup.func1(0x46cdcc0, 0xc01692c5b0, 0xc00a6d1900)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/waitgroup.go:47 +0x10f
net/http.HandlerFunc.ServeHTTP(0xc00946da70, 0x46cdcc0, 0xc01692c5b0, 0xc00a6d1900)
    /usr/local/go/src/net/http/server.go:2007 +0x44
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithRequestInfo.func1(0x46cdcc0, 0xc01692c5b0, 0xc00a6d1800)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/requestinfo.go:39 +0x274
net/http.HandlerFunc.ServeHTTP(0xc00946daa0, 0x46cdcc0, 0xc01692c5b0, 0xc00a6d1800)
    /usr/local/go/src/net/http/server.go:2007 +0x44
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithCacheControl.func1(0x46cdcc0, 0xc01692c5b0, 0xc00a6d1800)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/endpoints/filters/cachecontrol.go:31 +0xa8
net/http.HandlerFunc.ServeHTTP(0xc0094574c0, 0x46cdcc0, 0xc01692c5b0, 0xc00a6d1800)
    /usr/local/go/src/net/http/server.go:2007 +0x44
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/httplog.WithLogging.func1(0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:89 +0x2ca
net/http.HandlerFunc.ServeHTTP(0xc0094574e0, 0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /usr/local/go/src/net/http/server.go:2007 +0x44
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters.withPanicRecovery.func1(0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/filters/wrap.go:51 +0x13e
net/http.HandlerFunc.ServeHTTP(0xc009457500, 0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /usr/local/go/src/net/http/server.go:2007 +0x44
github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server.(*APIServerHandler).ServeHTTP(0xc00946dad0, 0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /go/src/github.com/rancher/k3s/vendor/k8s.io/apiserver/pkg/server/handler.go:189 +0x51
net/http.serverHandler.ServeHTTP(0xc00a6eeee0, 0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /usr/local/go/src/net/http/server.go:2802 +0xa4
net/http.initNPNRequest.ServeHTTP(0x46f3440, 0xc0041d8ed0, 0xc012957c00, 0xc00a6eeee0, 0x46c1380, 0xc010637e78, 0xc006b4fc00)
    /usr/local/go/src/net/http/server.go:3365 +0x8d
github.com/rancher/k3s/vendor/golang.org/x/net/http2.(*serverConn).runHandler(0xc00ae0db00, 0xc010637e78, 0xc006b4fc00, 0xc008e954c0)
    /go/src/github.com/rancher/k3s/vendor/golang.org/x/net/http2/server.go:2125 +0x9f
created by github.com/rancher/k3s/vendor/golang.org/x/net/http2.(*serverConn).processHeaders
    /go/src/github.com/rancher/k3s/vendor/golang.org/x/net/http2/server.go:1859 +0x4eb

gist:

https://gist.github.com/David-Igou/b64a760daa9bb39d10155dcdc7f5f59b

k3s args:

["--kube-apiserver-arg", "cloud-provider=external", "--kube-apiserver-arg", "allow-privileged=true", "--kube-apiserver-arg", "feature-gates=CSINodeInfo=true,CSIDriverRegistry=true,CSIBlockVolume=true,VolumeSnapshotDataSource=true", "--kube-controller-arg", "cloud-provider=external", "--kubelet-arg", "feature-gates=CSINodeInfo=true,CSIDriverRegistry=true,CSIBlockVolume=true", "--disable-cloud-controller", "--no-deploy", "local-storage", "--kubelet-arg", "authentication-token-webhook=true", "--kubelet-arg", "authorization-mode=Webhook"]

(this is pasted from my tfvars, not config.yaml)

dweomer commented 4 years ago

@David-Igou this looks specific to k3s, you may have more luck sharing there