Description of problem: Build one image,then check build log using "openshift kube buildLogs --id="'buildID'" when build status is running.No log return,the command just hold on. After build status is completed or failed,could get builds log. Version-Release number of selected component (if applicable): devenv-fedora_275 How reproducible: always Steps to Reproduce: 1.Change the WriteTimeout value from 10 to 300 ms in /data/src/github.com/openshift/origin/Godeps/_workspace/src/github.com/GoogleCloudPlatform/kubernetes/pkg/kubelet/server.go#L57 2.Pre-pull the docker images used in this sample. ./pullimages.sh 3.Launch openshift $ openshift start &> openshift.log & 4.Deploy the private docker registry within OpenShift: $ openshift kube apply -c registry-config.json 5.Create a build configuration for your application $ openshift kube create buildConfigs -c buildcfg/buildcfg.json 6.Trigger an initial build of your application $ curl -s -A "GitHub-Hookshot/github" -H "Content-Type:application/json" -H "X-Github-Event:push" -d @buildinvoke/pushevent.json http://localhost:8080/osapi/v1beta1/buildConfigHooks/build100/secret101/github 7.Monitor the builds and wait for the status to go to "runing" $ openshift kube list builds 8.Get log $ openshift kube buildLogs --id="3082d172-5dc7-11e4-af64-22000b458fd7" Actual results: Step 8: No log return, the command just hold on. Expected results: Should get build log Additional info: Get log from `openshift start` during build running. I1027 11:01:20.059484 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. I1027 11:01:20.061615 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. I1027 11:01:39.696744 00909 controller.go:95] Syncing build 3082d172-5dc7-11e4-af64-22000b458fd7 I1027 11:01:50.065257 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. I1027 11:01:50.067683 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. I1027 11:01:59.783645 00909 controller.go:95] Syncing build 3082d172-5dc7-11e4-af64-22000b458fd7 I1027 11:02:09.652268 00909 controller.go:95] Syncing build 3082d172-5dc7-11e4-af64-22000b458fd7 I1027 11:02:19.841344 00909 controller.go:95] Syncing build 3082d172-5dc7-11e4-af64-22000b458fd7 I1027 11:02:20.072993 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. I1027 11:02:20.077129 00909 docker.go:214] Docker Container:/drunk_goldstine is not managed by kubelet. E1027 11:02:29.695770 00909 iowatcher.go:88] Unable to decode an event from the watch stream: unexpected EOF E1027 11:02:29.696798 00909 reflector.go:101] failed to watch *api.Deployment: Get http://10.102.154.211:8080/osapi/v1beta1/watch/deployments?fields=&labels=&resourceVersion=0: EOF E1027 11:02:29.700045 00909 iowatcher.go:88] Unable to decode an event from the watch stream: unexpected EOF
Test on devenv-fedora_286, different behaviour appears with above hang-on issue: When curl build log from a running build, below error appears: [fedora@ip-10-67-172-6 origin]$ openshift kube buildLogs --id=2c0dcae7-5f18-11e4-bdc7-22000b4b9754 Not Found: "/proxy/minion/ip-10-67-172-6.ec2.internal/containerLogs/build-docker-2c0dcae7-5f18-11e4-bdc7-22000b4b9754/docker-build?follow=1"
(In reply to Wenjing Zheng from comment #1) > Test on devenv-fedora_286, different behaviour appears with above hang-on > issue: > When curl build log from a running build, below error appears: > [fedora@ip-10-67-172-6 origin]$ openshift kube buildLogs > --id=2c0dcae7-5f18-11e4-bdc7-22000b4b9754 > Not Found: > "/proxy/minion/ip-10-67-172-6.ec2.internal/containerLogs/build-docker- > 2c0dcae7-5f18-11e4-bdc7-22000b4b9754/docker-build?follow=1" This error is not just for running build, it's for all build states.
Tested on latest devenv-fedora_321, a different error appears when curl build log no matter build status is running or complete: [fedora@ip-10-187-37-239 sample-app]$ openshift kube list builds ID Status Pod ID ---------- ---------- ---------- b6a4b50e-6408-11e4-bb1c-22000b211344 complete build-docker-b6a4b50e-6408-11e4-bb1c-22000b211344 [fedora@ip-10-187-37-239 sample-app]$ openshift kube buildLogs --id=b6a4b50e-6408-11e4-bb1c-22000b211344 {"kind":"Status","creationTimestamp":null,"apiVersion":"v1beta1","status":"Failure","message":"No such build","code":500}
This PR should fix the problem: https://github.com/openshift/origin/pull/323
Test with devenv-fedora_348 During build running, getting buildlog always exit with error "F1107 02:37:30.880026 04623 kubecfg.go:519] Error: unexpected EOF". When build is completed,could get the whole log. vim pkg/cmd/client/kubecfg.go 505 func (c *KubeConfig) executeBuildLogRequest(method string, client *osclient.Client) bool { 506 if method != "buildLogs" { 507 return false 508 } 509 if len(c.ID) == 0 { 510 glog.Fatal("Build ID required") 511 } 512 request := client.Verb("GET").Namespace(c.getNamespace()).Path("redirect").Path("buildLogs").Path(c.ID) 513 readCloser, err := request.Stream() 514 if err != nil { 515 glog.Fatalf("Error: %v", err) 516 } 517 defer readCloser.Close() 518 if _, err := io.Copy(os.Stdout, readCloser); err != nil { 519 glog.Fatalf("Error: %v", err) 520 } 521 return true 522 } $ openshift kube buildLogs --id=b353988f-6626-11e4-bfb4-22000b603127 Q2014-11-07T02:35:14.576487824Z Sending build context to Docker daemon 93.18 kB H2014-11-07T02:35:14.576487824Z Sending build context to Docker daemon F2014-11-07T02:35:14.589134713Z Step 0 : FROM openshift/ruby-20-centos 22014-11-07T02:35:14.589646329Z ---> 53e44a9aff5e n2014-11-07T02:35:14.589812323Z Step 1 : RUN gem install sinatra sinatra-activerecord mysql2 --no-ri --no-rdoc 12014-11-07T02:35:14.626407967Z ---> Using cache 22014-11-07T02:35:14.626529532Z ---> cc4d7171a8c2 42014-11-07T02:35:14.626636795Z Step 2 : ADD . /tmp/ 22014-11-07T02:35:22.693311284Z ---> c0ee99e5e52f L2014-11-07T02:35:24.253212578Z Removing intermediate container d8640541a761 22014-11-07T02:35:24.253212578Z Step 3 : USER root =2014-11-07T02:35:24.416695676Z ---> Running in 835583bf89c6 22014-11-07T02:35:32.243814366Z ---> 58f402f50606 L2014-11-07T02:35:33.938147025Z Removing intermediate container 835583bf89c6 F2014-11-07T02:35:33.938147025Z Step 4 : RUN chown -R ruby:ruby /tmp/* =2014-11-07T02:35:34.204565810Z ---> Running in eda21c5cac4a 22014-11-07T02:35:42.464544449Z ---> 6f952a318a14 L2014-11-07T02:35:44.363060363Z Removing intermediate container eda21c5cac4a 22014-11-07T02:35:44.363060363Z Step 5 : USER ruby =2014-11-07T02:35:44.515308709Z ---> Running in 3512a9d905bb 22014-11-07T02:35:52.311252008Z ---> 6c6cde602c1c L2014-11-07T02:35:54.079435969Z Removing intermediate container 3512a9d905bb 62014-11-07T02:35:54.079435969Z Step 6 : WORKDIR /tmp/ =2014-11-07T02:35:54.217590479Z ---> Running in bffee3fedb0f 22014-11-07T02:36:01.795901058Z ---> 67d211eb5917 L2014-11-07T02:36:03.700806017Z Removing intermediate container bffee3fedb0f @2014-11-07T02:36:03.700806017Z Step 7 : ENV RACK_ENV production =2014-11-07T02:36:03.859608320Z ---> Running in 75a35b7137ae 22014-11-07T02:36:12.193727624Z ---> f7daf66c11c0 L2014-11-07T02:36:14.189123698Z Removing intermediate container 75a35b7137ae A2014-11-07T02:36:14.189123698Z Step 8 : ENV RAILS_ENV production =2014-11-07T02:36:14.333790107Z ---> Running in 12f83ed4c744 4[2014-11-07T02:36:22.948178983Z] ---> 9d254c494fe3 N[2014-11-07T02:36:24.792898232Z] Removing intermediate container 12f83ed4c744 6[2014-11-07T02:36:24.792898232Z] Step 9 : EXPOSE 8080 ?[2014-11-07T02:36:24.945535580Z] ---> Running in cd55ee9097ca F1107 02:36:33.702198 03688 kubecfg.go:519] Error: unexpected EOF
The problem is that the kubelet is closing the connection, cause it's WriteTimeout is set to 10 seconds, thats why you will see part of the streaming logs and after 10 seconds the EOF error. To see the log stream the WriteTimeout has to be bumped to some reasonable value. I set it to 5 minutes and it was enough. Problem is, what is a reasonable time value? Cause the build could take more than 5 minutes. Will create a PR to k8s thta will bump the WriteTimeout. Until than please test it with by bumping the WriteTimeout in the vendored k8s/kubelet/server.go#57 from `10 * time.Second` to `10 * time.Minute`
Hi Jakub, I have change WriteTimeout to 20 * time.Minute, streaming log still could get "Error: unexpected EOF".So when changed this parameter, need do other operations,like restarting docker or openshift service? Thanks in advance.
1.Update WriteTimeout and ReadTimeout from `10 * time.Second` to `10 * time.Minute` in k8s/kubelet/server.go#57 2.Recompile the code using 'make clean;hack/build-go.sh' 3.Start an OpenShift all-in-one server 4.Push a build 5.Get logs during the build running. Result: step 5: Could get log without EOF error.