kn service create with `--log-http` is pending for a long time

daisy-ycguo commented 4 years ago

What version of Knative Client?

$ ./kn version Version: v20191106-local-f1f6cfb-dirty Build Date: 2019-11-06 06:51:12 Git Revision: f1f6cfb Supported APIs:

serving.knative.dev/v1alpha1 (knative-serving v0.10.0)

What version of Knative Serving running on your cluster?

I don't know

Expected Behavior

./kn service create --image docker.io/ibmcom/fib-knative fib-knative --log-http could response correctly and print http logs to standard output.

Actual Behavior

./kn service create --image docker.io/ibmcom/fib-knative fib-knative --log-http keeps pending for 10 minutes and response a timeout error. But, ./kn service create --image docker.io/ibmcom/fib-knative fib-knative could response correctly.

Steps to Reproduce the Problem

Call ./kn service create --image docker.io/ibmcom/fib-knative fib-knative --log-http, it keeps pending and response timeout after 10 minutes.

$ ./kn service create --image docker.io/ibmcom/fib-knative fib-knative --log-http
===== REQUEST =====
GET /apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative HTTP/1.1
Host: c1.au-syd.containers.cloud.ibm.com:25013
User-Agent: kn/v0.0.0 (darwin/amd64) kubernetes/$Format
Accept: application/json, */*
Authorization: (REDACTED FOR PRIVACY)
Accept-Encoding: gzip

===== RESPONSE =====
HTTP/2.0 404 Not Found
Content-Length: 248
Content-Type: application/json
Date: Wed, 06 Nov 2019 06:59:12 GMT

{"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"services.serving.knative.dev \"fib-knative\" not found","reason":"NotFound","details":{"name":"fib-knative","group":"serving.knative.dev","kind":"services"},"code":404}

 * * * * * *
===== REQUEST =====
POST /apis/serving.knative.dev/v1alpha1/namespaces/default/services HTTP/1.1
Host: c1.au-syd.containers.cloud.ibm.com:25013
User-Agent: kn/v0.0.0 (darwin/amd64) kubernetes/$Format
Content-Length: 414
Accept: application/json, */*
Authorization: (REDACTED FOR PRIVACY)
Content-Type: application/json
Accept-Encoding: gzip

{"kind":"Service","apiVersion":"serving.knative.dev/v1alpha1","metadata":{"name":"fib-knative","namespace":"default","creationTimestamp":null},"spec":{"template":{"metadata":{"name":"fib-knative-qmnll-1","creationTimestamp":null,"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"}},"spec":{"containers":[{"name":"","image":"docker.io/ibmcom/fib-knative","resources":{}}]}}},"status":{}}

===== RESPONSE =====
HTTP/2.0 201 Created
Content-Length: 876
Content-Type: application/json
Date: Wed, 06 Nov 2019 06:59:13 GMT

{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306348","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]}}

 * * * * * *
Creating service 'fib-knative' in namespace 'default':

===== REQUEST =====
GET /apis/serving.knative.dev/v1alpha1/namespaces/default/services?fieldSelector=metadata.name%3Dfib-knative&timeout=10m30s&timeoutSeconds=630&watch=true HTTP/1.1
Host: c1.au-syd.containers.cloud.ibm.com:25013
User-Agent: kn/v0.0.0 (darwin/amd64) kubernetes/$Format
Accept: application/json, */*
Authorization: (REDACTED FOR PRIVACY)
Accept-Encoding: gzip

^@^@^@^@^@^@^@^@^@===== RESPONSE =====
HTTP/2.0 200 OK
Connection: close
Content-Type: application/json
Date: Wed, 06 Nov 2019 06:59:13 GMT

{"type":"ADDED","object":{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306363","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]},"status":{"conditions":[{"lastTransitionTime":"2019-11-06T06:59:13Z","status":"Unknown","type":"ConfigurationsReady"},{"lastTransitionTime":"2019-11-06T06:59:13Z","message":"Configuration \"fib-knative\" is waiting for a Revision to become ready.","reason":"RevisionMissing","status":"Unknown","type":"Ready"},{"lastTransitionTime":"2019-11-06T06:59:13Z","message":"Configuration \"fib-knative\" is waiting for a Revision to become ready.","reason":"RevisionMissing","status":"Unknown","type":"RoutesReady"}],"latestCreatedRevisionName":"fib-knative-qmnll-1","observedGeneration":1,"url":"http://fib-knative-default.159.23.66.2.xip.io"}}}
{"type":"MODIFIED","object":{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306433","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]},"status":{"conditions":[{"lastTransitionTime":"2019-11-06T06:59:17Z","status":"True","type":"ConfigurationsReady"},{"lastTransitionTime":"2019-11-06T06:59:13Z","message":"Configuration \"fib-knative\" is waiting for a Revision to become ready.","reason":"RevisionMissing","status":"Unknown","type":"Ready"},{"lastTransitionTime":"2019-11-06T06:59:13Z","message":"Configuration \"fib-knative\" is waiting for a Revision to become ready.","reason":"RevisionMissing","status":"Unknown","type":"RoutesReady"}],"latestCreatedRevisionName":"fib-knative-qmnll-1","latestReadyRevisionName":"fib-knative-qmnll-1","observedGeneration":1,"url":"http://fib-knative-default.159.23.66.2.xip.io"}}}
{"type":"MODIFIED","object":{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306446","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]},"status":{"address":{"url":"http://fib-knative.default.svc.cluster.local"},"conditions":[{"lastTransitionTime":"2019-11-06T06:59:17Z","status":"True","type":"ConfigurationsReady"},{"lastTransitionTime":"2019-11-06T06:59:17Z","message":"Ingress has not yet been reconciled.","reason":"IngressNotConfigured","status":"Unknown","type":"Ready"},{"lastTransitionTime":"2019-11-06T06:59:17Z","message":"Ingress has not yet been reconciled.","reason":"IngressNotConfigured","status":"Unknown","type":"RoutesReady"}],"latestCreatedRevisionName":"fib-knative-qmnll-1","latestReadyRevisionName":"fib-knative-qmnll-1","observedGeneration":1,"traffic":[{"latestRevision":true,"percent":100,"revisionName":"fib-knative-qmnll-1"}],"url":"http://fib-knative-default.159.23.66.2.xip.io"}}}
{"type":"MODIFIED","object":{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306453","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]},"status":{"address":{"url":"http://fib-knative.default.svc.cluster.local"},"conditions":[{"lastTransitionTime":"2019-11-06T06:59:17Z","status":"True","type":"ConfigurationsReady"},{"lastTransitionTime":"2019-11-06T06:59:17Z","message":"Waiting for VirtualService to be ready","reason":"Uninitialized","status":"Unknown","type":"Ready"},{"lastTransitionTime":"2019-11-06T06:59:17Z","message":"Waiting for VirtualService to be ready","reason":"Uninitialized","status":"Unknown","type":"RoutesReady"}],"latestCreatedRevisionName":"fib-knative-qmnll-1","latestReadyRevisionName":"fib-knative-qmnll-1","observedGeneration":1,"traffic":[{"latestRevision":true,"percent":100,"revisionName":"fib-knative-qmnll-1"}],"url":"http://fib-knative-default.159.23.66.2.xip.io"}}}
{"type":"MODIFIED","object":{"apiVersion":"serving.knative.dev/v1alpha1","kind":"Service","metadata":{"annotations":{"serving.knative.dev/creator":"IAM#guoyingc@cn.ibm.com","serving.knative.dev/lastModifier":"IAM#guoyingc@cn.ibm.com"},"creationTimestamp":"2019-11-06T06:59:13Z","generation":1,"name":"fib-knative","namespace":"default","resourceVersion":"306460","selfLink":"/apis/serving.knative.dev/v1alpha1/namespaces/default/services/fib-knative","uid":"f088b9fc-0062-11ea-b240-8217ff1c40ee"},"spec":{"template":{"metadata":{"annotations":{"client.knative.dev/user-image":"docker.io/ibmcom/fib-knative"},"creationTimestamp":null,"name":"fib-knative-qmnll-1"},"spec":{"containers":[{"image":"docker.io/ibmcom/fib-knative","name":"user-container","readinessProbe":{"successThreshold":1,"tcpSocket":{"port":0}},"resources":{}}],"timeoutSeconds":300}},"traffic":[{"latestRevision":true,"percent":100}]},"status":{"address":{"url":"http://fib-knative.default.svc.cluster.local"},"conditions":[{"lastTransitionTime":"2019-11-06T06:59:17Z","status":"True","type":"ConfigurationsReady"},{"lastTransitionTime":"2019-11-06T06:59:19Z","status":"True","type":"Ready"},{"lastTransitionTime":"2019-11-06T06:59:19Z","status":"True","type":"RoutesReady"}],"latestCreatedRevisionName":"fib-knative-qmnll-1","latestReadyRevisionName":"fib-knative-qmnll-1","observedGeneration":1,"traffic":[{"latestRevision":true,"percent":100,"revisionName":"fib-knative-qmnll-1"}],"url":"http://fib-knative-default.159.23.66.2.xip.io"}}}

 * * * * * *
630.224s Configuration "fib-knative" is waiting for a Revision to become ready.
630.224s ...
630.225s Ingress has not yet been reconciled.
630.225s Waiting for VirtualService to be ready
timeout: service 'fib-knative' not ready after 600 seconds

The output of ./kn service create --image docker.io/ibmcom/fib-knative fib-knative looks as below:

$ ./kn service create --image docker.io/ibmcom/fib-knative fib-knative
Creating service 'fib-knative' in namespace 'default':

  0.189s Configuration "fib-knative" is waiting for a Revision to become ready.
 15.955s ...
 16.031s Ingress has not yet been reconciled.
 16.091s Waiting for VirtualService to be ready
 17.407s Ready to serve.

Service 'fib-knative' created with latest revision 'fib-knative-fzkzc-1' and URL:
http://fib-knative-default.159.23.66.2.xip.io

rhuss commented 4 years ago

There is an issue with --log-http and event streams. Will go into mores details later (but its about that the logging will consume the whole response stream first, so that events are not distributed internally), but jusr at a conference, will be back at knative work on friday.

duglin commented 4 years ago

just hit this today too....

rhuss commented 4 years ago

The issue is that for logging with http, the HTTP response body is consumed to print out, but when in a watch situation, the response is a stream, so that logging only finished when the stream is finished. Which is far too late. Logging needs to be adapted, probably skipping to print out the response body and concentrating on headers and other meta info.

akerekes commented 4 years ago

Alternatively instead of tweaking how logging works we could change the hanging get to polling at: https://github.com/knative/client/blob/963788b7309ec3d538349222bad7b10403f9c134/pkg/wait/poll_watcher.go#L70-L78 if the --log-http flag was provided

rhuss commented 4 years ago

Polling should be only the second choice, for performance reasons (but is required on Google Cloud Run AFAIU). So we need to deal with this general way how watches work in K8s.