search

ovn-org / ovn-kubernetes

A robust Kubernetes networking platform
https://ovn-kubernetes.io/
Apache License 2.0
818 stars 338 forks source link

Kubevirt e2es: "with pre-copy should keep connectivity" stage fails because of webhook issue #3902

Closed martinkennelly closed 11 months ago

martinkennelly commented 1 year ago 
Sep 13 10:56:49.180: Unexpected error:
        <*errors.StatusError | 0xc00078a1e0>: {
            ErrStatus: {
                TypeMeta: {Kind: "", APIVersion: ""},
                ListMeta: {
                    SelfLink: "",
                    ResourceVersion: "",
                    Continue: "",
                    RemainingItemCount: nil,
                },
                Status: "Failure",
                Message: "Internal error occurred: failed calling webhook \"virtualmachines-mutator.kubevirt.io\": failed to call webhook: Post \"[https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s\](https://virt-api.kubevirt.svc/virtualmachines-mutate?timeout=10s\)": context deadline exceeded",
                Reason: "InternalError",
                Details: {
                    Name: "",
                    Group: "",
                    Kind: "",
                    UID: "",
                    Causes: [
                        {
                            Type: "",
                            Message: "failed calling webhook \"virtualmachines-mutator.kubevirt.io\": failed to call webhook: Post \"[https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s\](https://virt-api.kubevirt.svc/virtualmachines-mutate?timeout=10s\)": context deadline exceeded",
                            Field: "",
                        },
                    ],
                    RetryAfterSeconds: 0,
                },
                Code: 500,
            },
        }
        Internal error occurred: failed calling webhook "virtualmachines-mutator.kubevirt.io": failed to call webhook: Post "[https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s](https://virt-api.kubevirt.svc/virtualmachines-mutate?timeout=10s)": context deadline exceeded
    occurred

https://github.com/ovn-org/ovn-kubernetes/actions/runs/6171091090/job/16749493472?pr=3898

/assign @qinqon

martinkennelly commented 1 year ago

Side chatted @qinqon and it seems he needs logs from the kubevirt namespace but its not available in the GH log archive.

martinkennelly commented 1 year ago

Seen this again in #3898

qinqon commented 1 year ago

From job uploaded artifacts we have the kubevirt k8s apiserver logs, this is the error 

2023-09-15T12:51:02.889719392Z stderr F W0915 12:51:02.889629       1 dispatcher.go:196] Failed calling webhook, failing closed virtualmachines-mutator.kubevirt.io: failed calling webhook "virtualmachines-mutator.kubevirt.io": failed to call webhook: Post "https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s": context deadline exceeded
2023-09-15T12:51:02.890160292Z stderr F I0915 12:51:02.890105       1 trace.go:219] Trace[821840061]: "Create" accept:application/json, */*,audit-id:48843a9f-9fc1-4b49-b707-5912d3a5ab8a,client:172.18.0.1,protocol:HTTP/2.0,resource:virtualmachines,scope:resource,url:/apis/kubevirt.io/v1alpha3/namespaces/kv-live-migration-456/virtualmachines,user-agent:Go-http-client/2.0,verb:POST (15-Sep-2023 12:50:52.886) (total time: 10004ms):
2023-09-15T12:51:02.890172292Z stderr F Trace[821840061]: ---"limitedReadBody succeeded" len:994 0ms (12:50:52.886)
2023-09-15T12:51:02.890175692Z stderr F Trace[821840061]: ---"About to convert to expected version" 0ms (12:50:52.886)
2023-09-15T12:51:02.890188792Z stderr F Trace[821840061]: ---"Conversion done" 0ms (12:50:52.886)
2023-09-15T12:51:02.890192192Z stderr F Trace[821840061]: ---"About to store object in database" 0ms (12:50:52.886)
2023-09-15T12:51:02.890196392Z stderr F Trace[821840061]: ["Call mutating webhook" configuration:virt-api-mutator,webhook:virtualmachines-mutator.kubevirt.io,resource:kubevirt.io/v1alpha3, Resource=virtualmachines,subresource:,operation:CREATE,UID:2049a819-91ac-47c0-8aae-1edfcda35912 10002ms (12:50:52.887)]
2023-09-15T12:51:02.890199792Z stderr F Trace[821840061]: ---"Write to database call failed" len:994,err:Internal error occurred: failed calling webhook "virtualmachines-mutator.kubevirt.io": failed to call webhook: Post "https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s": context deadline exceeded 1ms (12:51:02.889)
2023-09-15T12:51:02.890202692Z stderr F Trace[821840061]: [10.004009834s] [10.004009834s] END
2023-09-15T12:51:02.890307091Z stderr F I0915 12:51:02.890235       1 httplog.go:132] "HTTP" verb="POST" URI="/apis/kubevirt.io/v1alpha3/namespaces/kv-live-migration-456/virtualmachines" latency="10.004920334s" userAgent="Go-http-client/2.0" audit-ID="48843a9f-9fc1-4b49-b707-5912d3a5ab8a" srcIP="172.18.0.1:47790" apf_pl="exempt" apf_fs="exempt" apf_execution_time="10.004689634s" resp=500 statusStack=<
2023-09-15T12:51:02.890311791Z stderr F     
2023-09-15T12:51:02.890314991Z stderr F     goroutine 96790 [running]:
2023-09-15T12:51:02.890318191Z stderr F     k8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc011e28b00, 0xc00fcef470?)
2023-09-15T12:51:02.890321291Z stderr F         vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:320 +0x105
2023-09-15T12:51:02.890324091Z stderr F     k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc011e28b00, 0xc00b518b00?)
2023-09-15T12:51:02.890326991Z stderr F         vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:300 +0x25
2023-09-15T12:51:02.890443291Z stderr F     k8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc00fcef4a0, 0x860000c000074c00?)
2023-09-15T12:51:02.890448591Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:239 +0x1c8
2023-09-15T12:51:02.890451591Z stderr F     k8s.io/apiserver/pkg/endpoints/metrics.(*ResponseWriterDelegator).WriteHeader(0x288afe0?, 0xc00b518b00?)
2023-09-15T12:51:02.890454391Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:726 +0x29
2023-09-15T12:51:02.890457591Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.(*deferredResponseWriter).Write(0xc01603a7e0, {0xc01e614000, 0x235, 0x300000})
2023-09-15T12:51:02.890460591Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:243 +0x642
2023-09-15T12:51:02.890463391Z stderr F     encoding/json.(*Encoder).Encode(0xc00d837558, {0x2d170e0, 0xc014b21d60})
2023-09-15T12:51:02.890466591Z stderr F         /usr/local/go/src/encoding/json/stream.go:231 +0x1fe
2023-09-15T12:51:02.890469391Z stderr F     k8s.io/apimachinery/pkg/runtime/serializer/json.(*Serializer).doEncode(0x0?, {0x3397130?, 0xc014b21d60?}, {0x338c380, 0xc01603a7e0})
2023-09-15T12:51:02.890472291Z stderr F         vendor/k8s.io/apimachinery/pkg/runtime/serializer/json/json.go:246 +0x19a
2023-09-15T12:51:02.890475191Z stderr F     k8s.io/apimachinery/pkg/runtime/serializer/json.(*Serializer).Encode(0xc005842be0, {0x3397130, 0xc014b21d60}, {0x338c380, 0xc01603a7e0})
2023-09-15T12:51:02.890478091Z stderr F         vendor/k8s.io/apimachinery/pkg/runtime/serializer/json/json.go:220 +0xfc
2023-09-15T12:51:02.890481291Z stderr F     k8s.io/apimachinery/pkg/runtime/serializer/versioning.(*codec).doEncode(0xc014b21e00, {0x3397130, 0xc014b21d60}, {0x338c380, 0xc01603a7e0}, {0x0?, 0x0?})
2023-09-15T12:51:02.890484091Z stderr F         vendor/k8s.io/apimachinery/pkg/runtime/serializer/versioning/versioning.go:268 +0xd45
2023-09-15T12:51:02.890487191Z stderr F     k8s.io/apimachinery/pkg/runtime/serializer/versioning.(*codec).encode(0xc014b21e00, {0x3397130, 0xc014b21d60}, {0x338c380, 0xc01603a7e0}, {0x0?, 0x0?})
2023-09-15T12:51:02.890520191Z stderr F         vendor/k8s.io/apimachinery/pkg/runtime/serializer/versioning/versioning.go:214 +0x167
2023-09-15T12:51:02.890523791Z stderr F     k8s.io/apimachinery/pkg/runtime/serializer/versioning.(*codec).Encode(0x33b46b8?, {0x3397130?, 0xc014b21d60?}, {0x338c380?, 0xc01603a7e0?})
2023-09-15T12:51:02.890526791Z stderr F         vendor/k8s.io/apimachinery/pkg/runtime/serializer/versioning/versioning.go:207 +0x33
2023-09-15T12:51:02.890529891Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.SerializeObject({0x2db7e00, 0x10}, {0x7fc81eb06770, 0xc014b21e00}, {0x33b3328?, 0xc016561d00}, 0xc00bcf3000, 0x1f4, {0x3397130, 0xc014b21d60})
2023-09-15T12:51:02.890532791Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:111 +0xa87
2023-09-15T12:51:02.890535791Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.WriteObjectNegotiated.func2()
2023-09-15T12:51:02.890538591Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:292 +0x21d
2023-09-15T12:51:02.890541491Z stderr F     k8s.io/apiserver/pkg/endpoints/request.(*durationTracker).Track(0xc00fcef320, 0xc00d333c70)
2023-09-15T12:51:02.890544391Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/request/webhook_duration.go:75 +0x93
2023-09-15T12:51:02.890547491Z stderr F     k8s.io/apiserver/pkg/endpoints/request.TrackSerializeResponseObjectLatency({0x33b46b8?, 0xc00fcef650?}, 0xc00d333c70)
2023-09-15T12:51:02.890550391Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/request/webhook_duration.go:216 +0x5e
2023-09-15T12:51:02.890553691Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.WriteObjectNegotiated({0x33b2ea8, 0xc0068140c0}, {0x33b32c8, 0x4be5220}, {{0xc008368b00?, 0x4bb31a0?}, {0xc00a3aecc0?, 0x1d?}}, {0x33b3328, 0xc016561d00}, ...)
2023-09-15T12:51:02.890556591Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:288 +0x789
2023-09-15T12:51:02.890559491Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.ErrorNegotiated({0x338ba40?, 0xc014b21cc0?}, {0x33b2ea8, 0xc0068140c0}, {{0xc008368b00?, 0x0?}, {0xc00a3aecc0?, 0xc0068140c0?}}, {0x33b3328, 0xc016561d00}, ...)
2023-09-15T12:51:02.890562291Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:329 +0x285
2023-09-15T12:51:02.890580191Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers.(*RequestScope).err(...)
2023-09-15T12:51:02.890589891Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/rest.go:115
2023-09-15T12:51:02.890592991Z stderr F     k8s.io/apiserver/pkg/endpoints/handlers.createHandler.func1({0x33b3328, 0xc016561d00}, 0xc00bcf3000)
2023-09-15T12:51:02.890595991Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/handlers/create.go:217 +0x2565
2023-09-15T12:51:02.890910791Z stderr F     k8s.io/apiserver/pkg/endpoints/metrics.InstrumentHandlerFunc.func1({0x33b3328?, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.890916391Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:579 +0x214
2023-09-15T12:51:02.890919391Z stderr F     net/http.HandlerFunc.ServeHTTP(0x0?, {0x33b3328?, 0xc016561be0?}, 0xc00d839798?)
2023-09-15T12:51:02.890922391Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.890925391Z stderr F     k8s.io/apiserver/pkg/server/filters.withWaitGroup.func1({0x33b3328?, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.890928291Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/waitgroup.go:77 +0x766
2023-09-15T12:51:02.890931391Z stderr F     net/http.HandlerFunc.ServeHTTP(0x3390be0?, {0x33b3328?, 0xc016561be0?}, 0xc0043038f0?)
2023-09-15T12:51:02.890934291Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.890937291Z stderr F     k8s.io/apiextensions-apiserver/pkg/apiserver.(*crdHandler).ServeHTTP(0xc000fff4a0, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.890940191Z stderr F         vendor/k8s.io/apiextensions-apiserver/pkg/apiserver/customresource_handler.go:358 +0x102f
2023-09-15T12:51:02.890943091Z stderr F     k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc0045cf740, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.890951491Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:249 +0x4c6
2023-09-15T12:51:02.890954491Z stderr F     k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc01cefdb30?, {0x33b3328?, 0xc016561be0?}, 0x0?)
2023-09-15T12:51:02.890957391Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:235 +0x73
2023-09-15T12:51:02.890960391Z stderr F     k8s.io/apiserver/pkg/server.director.ServeHTTP({{0x2dc8285?, 0x0?}, 0xc000d67c20?, 0xc000769f10?}, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.890963291Z stderr F         vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x61f
2023-09-15T12:51:02.896608886Z stderr F     k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc000846b40, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896619886Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:255 +0x2cd
2023-09-15T12:51:02.896623186Z stderr F     k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc01cefdb30?, {0x33b3328?, 0xc016561be0?}, 0xc00bcf2500?)
2023-09-15T12:51:02.896626186Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:235 +0x73
2023-09-15T12:51:02.896629386Z stderr F     k8s.io/apiserver/pkg/server.director.ServeHTTP({{0x2db3dce?, 0x5?}, 0xc000dc13b0?, 0xc0002968c0?}, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896632486Z stderr F         vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x61f
2023-09-15T12:51:02.896635586Z stderr F     k8s.io/kube-aggregator/pkg/apiserver.(*proxyHandler).ServeHTTP(0xc0025ddb60?, {0x33b3328?, 0xc016561be0?}, 0x4b?)
2023-09-15T12:51:02.896638486Z stderr F         vendor/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go:125 +0x172
2023-09-15T12:51:02.896641486Z stderr F     k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc004d10a80, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896644386Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:249 +0x4c6
2023-09-15T12:51:02.896647286Z stderr F     k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc01cefdb30?, {0x33b3328?, 0xc016561be0?}, 0x88ff52?)
2023-09-15T12:51:02.896650186Z stderr F         vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:235 +0x73
2023-09-15T12:51:02.896653586Z stderr F     k8s.io/apiserver/pkg/server.director.ServeHTTP({{0x2db61e0?, 0x40b994?}, 0xc001fe3290?, 0xc0001ee930?}, {0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896656486Z stderr F         vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x61f
2023-09-15T12:51:02.896659286Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896667886Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:110 +0x1ca
2023-09-15T12:51:02.896670886Z stderr F     net/http.HandlerFunc.ServeHTTP(0x33b46b8?, {0x33b3328?, 0xc016561be0?}, 0x4?)
2023-09-15T12:51:02.896673786Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896676686Z stderr F     k8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896679686Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filters/authorization.go:64 +0x4f4
2023-09-15T12:51:02.896682586Z stderr F     net/http.HandlerFunc.ServeHTTP(0x8c3f65?, {0x33b3328?, 0xc016561be0?}, 0xc000054780?)
2023-09-15T12:51:02.896685486Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896688386Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896691286Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:84 +0x190
2023-09-15T12:51:02.896694086Z stderr F     net/http.HandlerFunc.ServeHTTP(0x2c11420?, {0x33b3328?, 0xc016561be0?}, 0xb17d2a?)
2023-09-15T12:51:02.896696986Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896699886Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896713786Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:110 +0x1ca
2023-09-15T12:51:02.896716986Z stderr F     net/http.HandlerFunc.ServeHTTP(0xc017891180?, {0x33b3328?, 0xc016561be0?}, 0x40dc27?)
2023-09-15T12:51:02.896719986Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896722786Z stderr F     k8s.io/apiserver/pkg/server/filters.WithPriorityAndFairness.func2.9()
2023-09-15T12:51:02.896725586Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/priority-and-fairness.go:292 +0xf6
2023-09-15T12:51:02.896728386Z stderr F     k8s.io/apiserver/pkg/util/flowcontrol.(*configController).Handle.func2()
2023-09-15T12:51:02.896731186Z stderr F         vendor/k8s.io/apiserver/pkg/util/flowcontrol/apf_filter.go:191 +0x1e7
2023-09-15T12:51:02.896733986Z stderr F     k8s.io/apiserver/pkg/util/flowcontrol.immediateRequest.Finish(...)
2023-09-15T12:51:02.896736886Z stderr F         vendor/k8s.io/apiserver/pkg/util/flowcontrol/apf_controller.go:968
2023-09-15T12:51:02.896740086Z stderr F     k8s.io/apiserver/pkg/util/flowcontrol.(*configController).Handle(0xc00076b900, {0x33b46b8?, 0xc00fcef650}, {0xc011e289a0?, {0x33b52f8?, 0xc017891140?}}, 0xc013119160?, 0x1?, 0xc00fcef4d0?, 0xc00556caf0)
2023-09-15T12:51:02.896743086Z stderr F         vendor/k8s.io/apiserver/pkg/util/flowcontrol/apf_filter.go:179 +0x782
2023-09-15T12:51:02.896745886Z stderr F     k8s.io/apiserver/pkg/server/filters.WithPriorityAndFairness.func2({0x33b3328?, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896748686Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/priority-and-fairness.go:295 +0xceb
2023-09-15T12:51:02.896751586Z stderr F     net/http.HandlerFunc.ServeHTTP(0x8c3f65?, {0x33b3328?, 0xc016561be0?}, 0xc000054780?)
2023-09-15T12:51:02.896754386Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896757186Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896760086Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:84 +0x190
2023-09-15T12:51:02.896762886Z stderr F     net/http.HandlerFunc.ServeHTTP(0x2c11420?, {0x33b3328?, 0xc016561be0?}, 0xb17d2a?)
2023-09-15T12:51:02.896765786Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896768686Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896771486Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:110 +0x1ca
2023-09-15T12:51:02.896774386Z stderr F     net/http.HandlerFunc.ServeHTTP(0x0?, {0x33b3328?, 0xc016561be0?}, 0x150?)
2023-09-15T12:51:02.896777186Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896780086Z stderr F     k8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896782986Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filters/impersonation.go:50 +0x21c
2023-09-15T12:51:02.896785786Z stderr F     net/http.HandlerFunc.ServeHTTP(0x8c3f65?, {0x33b3328?, 0xc016561be0?}, 0xc000054780?)
2023-09-15T12:51:02.896788686Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896791686Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896794486Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:84 +0x190
2023-09-15T12:51:02.896797286Z stderr F     net/http.HandlerFunc.ServeHTTP(0x2c11420?, {0x33b3328?, 0xc016561be0?}, 0xb17d2a?)
2023-09-15T12:51:02.896800186Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896802986Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896805786Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:110 +0x1ca
2023-09-15T12:51:02.896811486Z stderr F     net/http.HandlerFunc.ServeHTTP(0x8c3f65?, {0x33b3328?, 0xc016561be0?}, 0xc000054780?)
2023-09-15T12:51:02.896814586Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896817486Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896820286Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:84 +0x190
2023-09-15T12:51:02.896823186Z stderr F     net/http.HandlerFunc.ServeHTTP(0x2c11420?, {0x33b3328?, 0xc016561be0?}, 0xb17d2a?)
2023-09-15T12:51:02.896825986Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896828886Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackCompleted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896831686Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:110 +0x1ca
2023-09-15T12:51:02.896834486Z stderr F     net/http.HandlerFunc.ServeHTTP(0x33b46b8?, {0x33b3328?, 0xc016561be0?}, 0x33785e8?)
2023-09-15T12:51:02.896837386Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896840286Z stderr F     k8s.io/apiserver/pkg/endpoints/filters.withAuthentication.func1({0x33b3328, 0xc016561be0}, 0xc00bcf3000)
2023-09-15T12:51:02.896843086Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filters/authentication.go:80 +0x622
2023-09-15T12:51:02.896845886Z stderr F     net/http.HandlerFunc.ServeHTTP(0x33b46b8?, {0x33b3328?, 0xc016561be0?}, 0x33784e0?)
2023-09-15T12:51:02.896848686Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896851486Z stderr F     k8s.io/apiserver/pkg/endpoints/filterlatency.trackStarted.func1({0x33b3328, 0xc016561be0}, 0xc00bcf2d00)
2023-09-15T12:51:02.896854386Z stderr F         vendor/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go:94 +0x383
2023-09-15T12:51:02.896857186Z stderr F     net/http.HandlerFunc.ServeHTTP(0xc002b41fd0?, {0x33b3328?, 0xc016561be0?}, 0x339eb10?)
2023-09-15T12:51:02.896869686Z stderr F         /usr/local/go/src/net/http/server.go:2109 +0x2f
2023-09-15T12:51:02.896872686Z stderr F     k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1()
2023-09-15T12:51:02.896875586Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:115 +0x70
2023-09-15T12:51:02.896878386Z stderr F     created by k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP
2023-09-15T12:51:02.896881286Z stderr F         vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:101 +0x1d8
2023-09-15T12:51:02.896884186Z stderr F  > addedInfo=<
2023-09-15T12:51:02.896887086Z stderr F     
2023-09-15T12:51:02.896890886Z stderr F     logging error output: "{\"kind\":\"Status\",\"apiVersion\":\"v1\",\"metadata\":{},\"status\":\"Failure\",\"message\":\"Internal error occurred: failed calling webhook \\\"virtualmachines-mutator.kubevirt.io\\\": failed to call webhook: Post \\\"https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s\\\": context deadline exceeded\",\"reason\":\"InternalError\",\"details\":{\"causes\":[{\"message\":\"failed calling webhook \\\"virtualmachines-mutator.kubevirt.io\\\": failed to call webhook: Post \\\"https://virt-api.kubevirt.svc:443/virtualmachines-mutate?timeout=10s\\\": context deadline exceeded\"}]},\"code\":500}\n"
2023-09-15T12:51:02.896894086Z stderr F  >
qinqon commented 1 year ago

So webhook goes to k8s apiserver and that goes to kubevirt virt-api, but somehow is timing out.

qinqon commented 1 year ago

test PR https://github.com/qinqon/ovn-kubernetes/actions/runs/6309440300#artifacts

qinqon commented 1 year ago

Looks like is always happening with dual stack, I am printing the endpoint slices of the virt-api service.

martinkennelly commented 1 year ago

@qinqon Thank you for working so hard on this - we do appreciate it

qinqon commented 12 months ago

webhook services is patch everytime VM is created 

{"component":"virt-operator","level":"info","msg":"service kubevirt-operator-webhook patched with [{ \"op\": \"replace\", \"path\": \"/spec\", \"value\": {\"ports\":[{\"name\":\"webhooks\",\"protocol\":\"TCP\",\"port\":443,\"targetPort\":\"webhooks\"}],\"selector\":{\"kubevirt.io\":\"virt-operator\"},\"clusterIP\":\"10.96.98.173\",\"type\":\"ClusterIP\",\"sessionAffinity\":\"None\"} }]","pos":"core.go:142","timestamp":"2023-10-03T10:02:28.031912Z"}
{"component":"virt-operator","level":"info","msg":"service virt-exportproxy patched with [{ \"op\": \"replace\", \"path\": \"/spec\", \"value\": {\"ports\":[{\"protocol\":\"TCP\",\"port\":443,\"targetPort\":8443}],\"selector\":{\"kubevirt.io\":\"virt-exportproxy\"},\"clusterIP\":\"10.96.183.249\",\"type\":\"ClusterIP\",\"sessionAffinity\":\"None\"} }]","pos":"core.go:142","timestamp":"2023-10-03T10:02:28.034368Z"}
martinkennelly commented 12 months ago

@qinqon we had a short discussion. API server request (host net ns) to webhook (behind a service) is failing with context deadline exceeded. No indication that webhook received any request. @qinqon will test to see when the service is available from the host netns.

qinqon commented 12 months ago

I have put some traces at kubevirt and looks kubevirt code that runs on mutate is being call

2023-10-05T11:44:04.175969406Z stderr F {"component":"virt-api","level":"info","msg":"deleteme, ServeVMs","pos":"mutating-webhook.go:81","timestamp":"2023-10-05T11:44:04.173064Z"}
2023-10-05T11:44:04.176018308Z stderr F {"component":"virt-api","level":"info","msg":"deleteme, serve","pos":"mutating-webhook.go:45","timestamp":"2023-10-05T11:44:04.175862Z"}
2023-10-05T11:44:07.615662083Z stderr F {"component":"virt-api","contentLength":370,"level":"info","method":"GET","pos":"filter.go:47","proto":"HTTP/1.1","remoteAddress":"10.244.0.2","statusCode":200,"timestamp":"2023-10-05T11:44:07.615506Z","url":"/apis/subresources.kubevirt.io/v1/healthz","username":"-"}
2023-10-05T11:44:09.052018037Z stderr F {"component":"virt-api","contentLength":3205,"level":"info","method":"GET","pos":"filter.go:47","proto":"HTTP/1.1","remoteAddress":"100.64.0.2","statusCode":200,"timestamp":"2023-10-05T11:44:09.051792Z","url":"/apis/subresources.kubevirt.io/v1","username":"-"}
qinqon commented 11 months ago

So diggint more at kubevirt looks like the webhook is stuck reading the http body 

func GetAdmissionReview(r *http.Request) (*admissionv1.AdmissionReview, error) {
        var body []byte
        if r.Body != nil {
                if data, err := io.ReadAll(r.Body); err == nil {
                        body = data
                }
        }

I will check if maybe err is != nil

npinaeva commented 11 months ago

one more failure https://github.com/ovn-org/ovn-kubernetes/actions/runs/6429137813/job/17458578688?pr=3949

trozet commented 11 months ago

Looks like it is still happening https://github.com/ovn-org/ovn-kubernetes/actions/runs/6498018498/job/17649428952?pr=3955 in #3955

qinqon commented 11 months ago

Looks like it is still happening https://github.com/ovn-org/ovn-kubernetes/actions/runs/6498018498/job/17649428952?pr=3955 in #3955

This error is different

STEP: worker1: after live migrate, migration #1: Check tcp connection is not broken
Oct 12 17:05:29.237: FAIL: Timed out after 60.000s.
worker1: after live migrate, migration #1: Check tcp connection is not broken
Expected success, but got an error:
    <*errors.errorString | 0xc00041b010>: {
        s: "http connection to virtual machine was broken",
    }
    http connection to virtual machine was broken

Full Stack Trace

Are we sure that PR is not broken live migration ? problem is that the tcp connection is being broken after live migration.

qinqon commented 11 months ago

Ahh well is a change at conformance is totally unrelated, can we open new one in case we see it again ?

trozet commented 11 months ago

Here is another flake:

https://github.com/ovn-org/ovn-kubernetes/actions/runs/6533348232/job/17739388992?pr=3678

trozet commented 11 months ago 
2023-10-16T13:01:52.2871286Z     with pre-copy should keep connectivity [It]
2023-10-16T13:01:52.2872385Z     /home/runner/work/ovn-kubernetes/ovn-kubernetes/test/e2e/kubevirt.go:647
2023-10-16T13:01:52.2873012Z 
2023-10-16T13:01:52.2876113Z     Oct 16 13:01:50.300: Expected success, but got an error:
2023-10-16T13:01:52.2876891Z         <*errors.StatusError | 0xc000758460>: {
2023-10-16T13:01:52.2877468Z             ErrStatus: {
2023-10-16T13:01:52.2878140Z                 TypeMeta: {Kind: "", APIVersion: ""},
2023-10-16T13:01:52.2878744Z                 ListMeta: {
2023-10-16T13:01:52.2879286Z                     SelfLink: "",
2023-10-16T13:01:52.2879926Z                     ResourceVersion: "",
2023-10-16T13:01:52.2880636Z                     Continue: "",
2023-10-16T13:01:52.2881302Z                     RemainingItemCount: nil,
2023-10-16T13:01:52.2881839Z                 },
2023-10-16T13:01:52.2882292Z                 Status: "Failure",
2023-10-16T13:01:52.2885492Z                 Message: "Internal error occurred: Internal error occurred: failed calling webhook \"migrations-mutator.kubevirt.io\": failed to call webhook: Post \"https://virt-api.kubevirt.svc:443/migration-mutate-create?timeout=10s\": context deadline exceeded",
2023-10-16T13:01:52.2887576Z                 Reason: "InternalError",
2023-10-16T13:01:52.2888121Z                 Details: {
2023-10-16T13:01:52.2888619Z                     Name: "",
2023-10-16T13:01:52.2889437Z                     Group: "",
2023-10-16T13:01:52.2889949Z                     Kind: "",
2023-10-16T13:01:52.2890532Z                     UID: "",
2023-10-16T13:01:52.2891034Z                     Causes: [
2023-10-16T13:01:52.2891502Z                         {
2023-10-16T13:01:52.2892068Z                             Type: "",
2023-10-16T13:01:52.2896009Z                             Message: "Internal error occurred: failed calling webhook \"migrations-mutator.kubevirt.io\": failed to call webhook: Post \"https://virt-api.kubevirt.svc:443/migration-mutate-create?timeout=10s\": context deadline exceeded",
2023-10-16T13:01:52.2897952Z                             Field: "",
2023-10-16T13:01:52.2898488Z                         },
2023-10-16T13:01:52.2903852Z                     ],
2023-10-16T13:01:52.2904728Z                     RetryAfterSeconds: 0,
2023-10-16T13:01:52.2905241Z                 },
2023-10-16T13:01:52.2905669Z                 Code: 500,
2023-10-16T13:01:52.2906074Z             },
qinqon commented 11 months ago 
2023-10-16T13:01:52.2871286Z     �[91m�[1mwith pre-copy should keep connectivity [It]�[0m
2023-10-16T13:01:52.2872385Z     �[90m/home/runner/work/ovn-kubernetes/ovn-kubernetes/test/e2e/kubevirt.go:647�[0m
2023-10-16T13:01:52.2873012Z 
2023-10-16T13:01:52.2876113Z     �[91mOct 16 13:01:50.300: Expected success, but got an error:
2023-10-16T13:01:52.2876891Z         <*errors.StatusError | 0xc000758460>: {
2023-10-16T13:01:52.2877468Z             ErrStatus: {
2023-10-16T13:01:52.2878140Z                 TypeMeta: {Kind: "", APIVersion: ""},
2023-10-16T13:01:52.2878744Z                 ListMeta: {
2023-10-16T13:01:52.2879286Z                     SelfLink: "",
2023-10-16T13:01:52.2879926Z                     ResourceVersion: "",
2023-10-16T13:01:52.2880636Z                     Continue: "",
2023-10-16T13:01:52.2881302Z                     RemainingItemCount: nil,
2023-10-16T13:01:52.2881839Z                 },
2023-10-16T13:01:52.2882292Z                 Status: "Failure",
2023-10-16T13:01:52.2885492Z                 Message: "Internal error occurred: Internal error occurred: failed calling webhook \"migrations-mutator.kubevirt.io\": failed to call webhook: Post \"https://virt-api.kubevirt.svc:443/migration-mutate-create?timeout=10s\": context deadline exceeded",
2023-10-16T13:01:52.2887576Z                 Reason: "InternalError",
2023-10-16T13:01:52.2888121Z                 Details: {
2023-10-16T13:01:52.2888619Z                     Name: "",
2023-10-16T13:01:52.2889437Z                     Group: "",
2023-10-16T13:01:52.2889949Z                     Kind: "",
2023-10-16T13:01:52.2890532Z                     UID: "",
2023-10-16T13:01:52.2891034Z                     Causes: [
2023-10-16T13:01:52.2891502Z                         {
2023-10-16T13:01:52.2892068Z                             Type: "",
2023-10-16T13:01:52.2896009Z                             Message: "Internal error occurred: failed calling webhook \"migrations-mutator.kubevirt.io\": failed to call webhook: Post \"https://virt-api.kubevirt.svc:443/migration-mutate-create?timeout=10s\": context deadline exceeded",
2023-10-16T13:01:52.2897952Z                             Field: "",
2023-10-16T13:01:52.2898488Z                         },
2023-10-16T13:01:52.2903852Z                     ],
2023-10-16T13:01:52.2904728Z                     RetryAfterSeconds: 0,
2023-10-16T13:01:52.2905241Z                 },
2023-10-16T13:01:52.2905669Z                 Code: 500,
2023-10-16T13:01:52.2906074Z             },

It's same error but different CRD, VirtualMachine vs VirtualMachineIntanceMigration, I will add som retries at creation here too.

It's not relation with migration per se.