/kind bug
What steps did you take and what happened:
I created the inferenceservice in the kubeflow with the sample , inferenceservice is READY, but the predict api did not return the expect response message 'Hello Python KFServing Sample!'
What did you expect to happen:
Get the response message with code 200 not 503.
Anything else you would like to add:
[Miscellaneous information that will assist in solving the issue.]
Here is my inferenceservice:
NAME URL READY DEFAULT TRAFFIC CANARY TRAFFIC AGE
custom-sample http://custom-sample.kfserving-test.example.com/v1/models/custom-sample True 100 20m
Here is my test request, it got 503 error.
curl -v -H "Host:custom-sample.kfserving-test.example.com" http://my_host:my_port/v1/models/custom-sample:predict
* Expire in 0 ms for 6 (transfer 0x1f1cfd09100)
* Expire in 1 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 1 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 2 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 7 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 9 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 4 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 50 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 50 ms for 1 (transfer 0x1f1cfd09100)
* Expire in 50 ms for 1 (transfer 0x1f1cfd09100)
* Trying 10.12.202.49...
* TCP_NODELAY set
* Expire in 200 ms for 4 (transfer 0x1f1cfd09100)
* Connected to my_host port my_port (#0)
> GET /v1/models/custom-sample:predict HTTP/1.1
> Host:custom-sample.kfserving-test.example.com
> User-Agent: curl/7.64.0
> Accept: */*
>
< HTTP/1.1 503 Service Unavailable
< date: Wed, 01 Jul 2020 09:44:07 GMT
< server: istio-envoy
< content-length: 0
<
* Connection #0 to host my_host left intact
here is my virtualservice:
NAME GATEWAYS HOSTS AGE
custom-sample [kubeflow-gateway.kubeflow] [custom-sample.kfserving-test.example.com] 6m56s
custom-sample-predictor-default [knative-serving/cluster-local-gateway kubeflow/kubeflow-gateway] [custom-sample-predictor-default.kfserving-test custom-sample-predictor-default.kfserving-test.example.com custom-sample-predictor-default.kfserving-test.svc custom-sample-predictor-default.kfserving-test.svc.cluster.local] 6m57s
custom-sample-predictor-default-mesh [mesh] [custom-sample-predictor-default.kfserving-test custom-sample-predictor-default.kfserving-test.svc custom-sample-predictor-default.kfserving-test.svc.cluster.local] 6m57s
Environment:
/etc/os-release):Issue Label Bot is not confident enough to auto-label this issue.
See dashboard for more details.
@songm28 Can you help check the istio ingress gateway or knative activator pod logs to see if there are informative errors there?
@yuzisun Here are the logs:
knative activator log got no error:
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n knative-serving logs pod/activator-67b7cb49df-5jx9l -c activator | grep error
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n knative-serving logs pod/activator-67b7cb49df-5jx9l -c istio-proxy | grep error
2020-06-29T07:14:05.159243Z info FLAG: --proxyComponentLogLevel="misc:error"
2020-06-29T07:14:05.168440Z info Envoy command: [-c /etc/istio/proxy/envoy-rev0.json --restart-epoch 0 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster activator.knative-serving --service-node sidecar~11.222.16.174~activator-67b7cb49df-5jx9l.knative-serving~knative-serving.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --log-format [Envoy (Epoch 0)] [%Y-%m-%d %T.%e][%t][%l][%n] %v -l warning --component-log-level misc:error --concurrency 2]
istio-ingressgateway logs got no error:
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n istio-system logs pod/istio-ingressgateway-db547d98-cf6dp | grep error
2020-06-19T09:59:28.018645Z info FLAG: --proxyComponentLogLevel="misc:error"
2020-06-19T09:59:28.026815Z info Envoy command: [-c /etc/istio/proxy/envoy-rev0.json --restart-epoch 0 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster istio-ingressgateway --service-node router~11.222.18.115~istio-ingressgateway-db547d98-cf6dp.istio-system~istio-system.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --log-format [Envoy (Epoch 0)] [%Y-%m-%d %T.%e][%t][%l][%n] %v -l warning --component-log-level misc:error]
2020-06-19T10:00:58.717552Z info Envoy command: [-c /etc/istio/proxy/envoy-rev1.json --restart-epoch 1 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster istio-ingressgateway --service-node router~11.222.18.115~istio-ingressgateway-db547d98-cf6dp.istio-system~istio-system.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --log-format [Envoy (Epoch 1)] [%Y-%m-%d %T.%e][%t][%l][%n] %v -l warning --component-log-level misc:error]
knative controller get some error:
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n knative-serving logs pod/controller-c6d7f946-5wdrf --tail=100 | grep error
{"level":"error","ts":"2020-07-01T09:43:44.764Z","logger":"controller.serverlessservice-controller","caller":"serverlessservice/serverlessservice.go:84","msg":"SKS resource in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"serverlessservice-controller","knative.dev/traceid":"fc74160b-ec0f-40db-b2be-794a55a16aae","knative.dev/key":"kubeflow/kfserving-hello-world-predictor-default-b6g6d","stacktrace":"knative.dev/serving/pkg/reconciler/serverlessservice.(*reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/serverlessservice/serverlessservice.go:84\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T09:43:44.783Z","logger":"controller.serverlessservice-controller","caller":"serverlessservice/serverlessservice.go:84","msg":"SKS resource in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"serverlessservice-controller","knative.dev/traceid":"5a152e11-7da7-4676-b676-7f29fd3a06cc","knative.dev/key":"kubeflow/kfserving-hello-world-predictor-default-b6g6d","stacktrace":"knative.dev/serving/pkg/reconciler/serverlessservice.(*reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/serverlessservice/serverlessservice.go:84\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T09:43:44.859Z","logger":"controller.serverlessservice-controller","caller":"serverlessservice/serverlessservice.go:84","msg":"SKS resource in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"serverlessservice-controller","knative.dev/traceid":"bf6e1f2b-3e7f-46ed-8297-a18289f566e3","knative.dev/key":"kubeflow/kfserving-hello-world-predictor-default-b6g6d","stacktrace":"knative.dev/serving/pkg/reconciler/serverlessservice.(*reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/serverlessservice/serverlessservice.go:84\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T09:43:44.871Z","logger":"controller.serverlessservice-controller","caller":"serverlessservice/serverlessservice.go:84","msg":"SKS resource in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"serverlessservice-controller","knative.dev/traceid":"b4af89d3-8c15-499d-87b2-d5cb2be84f1b","knative.dev/key":"kubeflow/kfserving-hello-world-predictor-default-b6g6d","stacktrace":"knative.dev/serving/pkg/reconciler/serverlessservice.(*reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/serverlessservice/serverlessservice.go:84\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T10:08:33.112Z","logger":"controller.route-controller","caller":"controller/controller.go:376","msg":"Reconcile error","commit":"6b0e5c6","knative.dev/controller":"route-controller","error":"failed to update Ingress: Operation cannot be fulfilled on ingresses.networking.internal.knative.dev \"custom-sample-predictor-default\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"knative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).handleErr\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:376\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:362\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
knative network get some error:
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n knative-serving logs pod/networking-istio-ff8674ddf-5vmcn --tail=50 | grep error
{"level":"error","ts":"2020-07-01T10:08:32.988Z","logger":"istiocontroller.ingress-controller","caller":"ingress/ingress.go:112","msg":"ingress \"kubeflow/pradeep-test\" in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","knative.dev/traceid":"b68485d4-db03-492e-aac3-ca4fce329cb5","knative.dev/key":"kubeflow/pradeep-test","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*Reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/ingress.go:112\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T10:08:32.988Z","logger":"istiocontroller.ingress-controller","caller":"ingress/ingress.go:112","msg":"ingress \"kfserving-test/custom-sample\" in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","knative.dev/traceid":"4d1d4de9-120a-4242-8c52-66b324685742","knative.dev/key":"kfserving-test/custom-sample","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*Reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/ingress.go:112\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T10:08:32.989Z","logger":"istiocontroller.ingress-controller","caller":"ingress/ingress.go:112","msg":"ingress \"kubeflow/kyle-test\" in work queue no longer exists","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","knative.dev/traceid":"dc53bbcb-d96e-415e-a709-3a1ee549caea","knative.dev/key":"kubeflow/kyle-test","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*Reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/ingress.go:112\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/serving/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/serving/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2020-07-01T10:08:32.989Z","logger":"istiocontroller.ingress-controller.status-manager","caller":"ingress/status.go:366","msg":"Probing of http://custom-sample-predictor-default.kfserving-test.svc:80/ failed, IP: 11.222.18.115:80, ready: false, error: unexpected status code: want [200], got 404 (depth: 0)","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*StatusProber).processWorkItem\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:366\nknative.dev/serving/pkg/reconciler/ingress.(*StatusProber).Start.func1\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:268"}
{"level":"error","ts":"2020-07-01T10:08:32.989Z","logger":"istiocontroller.ingress-controller.status-manager","caller":"ingress/status.go:366","msg":"Probing of http://custom-sample-predictor-default.kfserving-test:80/ failed, IP: 11.222.18.115:80, ready: false, error: unexpected status code: want [200], got 404 (depth: 0)","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*StatusProber).processWorkItem\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:366\nknative.dev/serving/pkg/reconciler/ingress.(*StatusProber).Start.func1\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:268"}
{"level":"error","ts":"2020-07-01T10:08:32.989Z","logger":"istiocontroller.ingress-controller.status-manager","caller":"ingress/status.go:366","msg":"Probing of http://custom-sample-predictor-default.kfserving-test.svc.cluster.local:80/ failed, IP: 11.222.18.115:80, ready: false, error: unexpected status code: want [200], got 404 (depth: 0)","commit":"6b0e5c6","knative.dev/controller":"ingress-controller","stacktrace":"knative.dev/serving/pkg/reconciler/ingress.(*StatusProber).processWorkItem\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:366\nknative.dev/serving/pkg/reconciler/ingress.(*StatusProber).Start.func1\n\t/home/prow/go/src/knative.dev/serving/pkg/reconciler/ingress/status.go:268"}
kubeflow/kfserving-controller logs got some error:
[root@8177266f5bb1 kubeflow-vessel-deployment]# kubectl -n kubeflow logs pod/kfserving-controller-manager-0 -c manager --tail=50 | grep error
{"level":"error","ts":1593596479.6021714,"logger":"kfserving-controller","msg":"Failed to reconcile","error":"Operation cannot be fulfilled on services.serving.knative.dev \"custom-sample-predictor-default\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"github.com/kubeflow/kfserving/vendor/github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/src/github.com/kubeflow/kfserving/vendor/github.com/go-logr/zapr/zapr.go:128\ngithub.com/kubeflow/kfserving/pkg/controller/inferenceservice.(*ReconcileService).Reconcile\n\t/go/src/github.com/kubeflow/kfserving/pkg/controller/inferenceservice/controller.go:154\ngithub.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/src/github.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:215\ngithub.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func1\n\t/go/src/github.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:158\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:134\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.Until\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:88"}
{"level":"error","ts":1593596479.6023371,"logger":"kubebuilder.controller","msg":"Reconciler error","controller":"kfserving-controller","request":"kfserving-test/custom-sample","error":"Operation cannot be fulfilled on services.serving.knative.dev \"custom-sample-predictor-default\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"github.com/kubeflow/kfserving/vendor/github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/src/github.com/kubeflow/kfserving/vendor/github.com/go-logr/zapr/zapr.go:128\ngithub.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/src/github.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:217\ngithub.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func1\n\t/go/src/github.com/kubeflow/kfserving/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:158\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:134\ngithub.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait.Until\n\t/go/src/github.com/kubeflow/kfserving/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:88"}
Issue-Label Bot is automatically applying the labels:
| Label | Probability |
| ------------- | ------------- |
| area/inference | 1.00 |
Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!
Links: app homepage, dashboard and code for this bot.
hmm those errors all look benign, did you see any request access logging in the istio ingress gateway pod log?
I am also experiencing the same issue and i get similar logs in all components.
I have exactly same issue, all samples that I try to install give 503 response. I'm also using GCP IAP and your @yuzisun examples on how to set them up.
Issue-Label Bot is automatically applying the labels:
| Label | Probability |
| ------------- | ------------- |
| area/engprod | 1.00 |
Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!
Links: app homepage, dashboard and code for this bot.
@yuzisun I am facing this issue also. I am able to curl the service (sklearn-iris-predictor-default.namespace.svc.cluster.local) completely fine from within the cluster but when I run from outside the cluster I am getting '503 errors'. I have turned on access logging and I can see the following in my cluster-local-gateway:
{"duration":"0","downstream_local_address":"10.1.0.198:80","upstream_transport_failure_reason":"-","response_code":"503","user_agent":"python-requests/2.24.0","response_flags":"NR","start_time":"2020-10-29T21:53:14.888Z","method":"GET","request_id":"0464fb51-04b4-4517-9f37-728977f2f779","upstream_host":"-","x_forwarded_for":"194.62.232.110, 34.120.137.230,10.10.10.6,10.1.2.2","requested_server_name":"-","bytes_received":"0","istio_policy_status":"-","bytes_sent":"0","upstream_cluster":"-","downstream_remote_address":"10.1.2.2:41212","path":"/kfserving/namespace/sklearn-iris:predict","authority":"sklearn-iris-predictor-default.namespace.svc.cluster.local","protocol":"HTTP/2","upstream_service_time":"-","upstream_local_address":"-"}
and in my ingress gateway:
{"authority":"sklearn-iris-predictor-default.namespace.svc.cluster.local","path":"/kfserving/namespace/sklearn-iris:predict","protocol":"HTTP/1.1","upstream_service_time":"71","upstream_local_address":"10.1.2.2:55614","duration":"72","upstream_transport_failure_reason":"-","route_name":"-","downstream_local_address":"10.1.2.2:80","user_agent":"python-requests/2.24.0","response_code":"503","response_flags":"URX","start_time":"2020-10-29T21:53:14.886Z","method":"GET","request_id":"35287f1e-cc46-46a4-8b6d-b49249cf9a5f","upstream_host":"10.1.2.215:80","x_forwarded_for":"194.62.232.110, 34.120.137.230,10.10.10.6","requested_server_name":"-","bytes_received":"0","istio_policy_status":"-","bytes_sent":"0","upstream_cluster":"outbound|80||cluster-local-gateway.istio-system.svc.cluster.local","downstream_remote_address":"10.10.10.6:55906"}