Bug 1694175

Summary:	Retrieving pod logs with follow flaky due to errors in kubelet log runtime
Product:	OpenShift Container Platform	Reporter:	Clayton Coleman <ccoleman>
Component:	Containers	Assignee:	Giuseppe Scrivano <gscrivan>
Status:	CLOSED ERRATA	QA Contact:	weiwei jiang <wjiang>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	4.1.0	CC:	aos-bugs, aos-cloud, mpatel, nagrawal
Target Milestone:	---
Target Release:	4.1.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:	1685225	Environment:
Last Closed:	2019-06-04 10:46:34 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Clayton Coleman 2019-03-29 17:16:14 UTC

We continue to experience the log follow snippet problem that we have a fix open for upstream.  It's still one of our top flakes 1/5-1/10 and needs to be resolved before GA.

fail [github.com/openshift/origin/test/extended/deployments/deployments.go:399]: Expected
    <string>: --> pre: Running hook pod ...
    --> pre: Success
    --> Scaling up deployment-test-2 from 0 to 1, scaling down deployment-test-1 from 0 to 0 (keep 1 pods available, don't exceed 2 pods)
        Scaling deployment-test-2 up to 1
    --> Success
to contain substring
    <string>: test pre hook executed
				

https://openshift-gce-devel.appspot.com/build/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-4.0/6249#openshift-tests-featuredeploymentconfig-deploymentconfigs-with-test-deployments-conformance-should-run-a-deployment-to-completion-and-then-scale-to-zero-suiteopenshiftconformanceparallelminimal

Comment 1 Mrunal Patel 2019-04-01 17:02:41 UTC

https://github.com/kubernetes/kubernetes/pull/73041 will be backported to origin once merged.

Comment 2 Giuseppe Scrivano 2019-04-01 19:44:53 UTC

backport here: https://github.com/openshift/origin/pull/21795

Comment 3 Mrunal Patel 2019-04-09 17:56:49 UTC

The PR is merged.

Comment 5 weiwei jiang 2019-04-11 08:35:55 UTC

Checked with the following downstream version, since the e2e passed, so move to verified.

# oc get clusterversion 
NAME      VERSION                             AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.0.0-0.nightly-2019-04-05-165550   True        False         4h33m   Cluster version is 4.0.0-0.nightly-2019-04-05-165550

➜  origin git:(master) ✗ ./_output/local/bin/linux/amd64/openshift-tests run-test "[Feature:DeploymentConfig] deploymentconfigs with test deployments [Conformance] should run a deployment to completion and then scale to zero [Suite:openshift/conformance/parallel/minimal]"
                                                                                                                               
Apr 11 15:30:42.737: INFO: Overriding default scale value of zero to 1
Apr 11 15:30:42.737: INFO: Overriding default milliseconds value of zero to 5000  
Apr 11 15:30:43.186: INFO: The --provider flag is not set.  Treating as a conformance test.  Some tests may not be run.              
Apr 11 15:30:43.194: INFO: >>> kubeConfig: kubeconfig  
Apr 11 15:30:43.195: INFO: Waiting up to 30m0s for all (but 100) nodes to be schedulable
Apr 11 15:30:44.627: INFO: Waiting up to 10m0s for all pods (need at least 0) in namespace 'kube-system' to be running and ready                  
Apr 11 15:30:45.694: INFO: 3 / 3 pods in namespace 'kube-system' are running and ready (1 seconds elapsed)
Apr 11 15:30:45.694: INFO: expected 0 pod replicas in namespace 'kube-system', 0 are Running and Ready.                                                  
Apr 11 15:30:45.694: INFO: Waiting up to 5m0s for all daemonsets in namespace 'kube-system' to start                                                 
Apr 11 15:30:45.807: INFO: e2e test version: v1.13.4+878221be4c                                    
Apr 11 15:30:45.904: INFO: kube-apiserver version: v1.13.4+ab11434         
[BeforeEach] [Top Level]                                                                                                       
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/util/test.go:69
[BeforeEach] [Feature:DeploymentConfig] deploymentconfigs                         
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:153
STEP: Creating a kubernetes client                                
Apr 11 15:30:45.906: INFO: >>> kubeConfig: kubeconfig
[BeforeEach] [Feature:DeploymentConfig] deploymentconfigs                                                                                         
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/util/cli.go:96
Apr 11 15:30:53.187: INFO: configPath is now "/tmp/configfile028145405"                                                                                  
Apr 11 15:30:53.187: INFO: The user is now "e2e-test-cli-deployment-cxnr9-user"                                                                      
Apr 11 15:30:53.187: INFO: Creating project "e2e-test-cli-deployment-cxnr9"                        
Apr 11 15:30:53.395: INFO: Waiting on permissions in project "e2e-test-cli-deployment-cxnr9" ...
Apr 11 15:30:53.489: INFO: Waiting for ServiceAccount "default" to be provisioned...     
Apr 11 15:30:53.700: INFO: Waiting for ServiceAccount "deployer" to be provisioned...
Apr 11 15:30:53.898: INFO: Waiting for ServiceAccount "builder" to be provisioned...
Apr 11 15:30:54.094: INFO: Waiting for RoleBinding {{"" ""} {"system:image-pullers" "" "e2e-test-cli-deployment-cxnr9" "" "" "" '\x00' "0001-01-01 00:00:00 +0000 UTC" <nil> %!q(*int64=<nil>) map[] map["openshift.io/description":"Allows all pods in this namespace to pull i
mages from this namespace.  It is auto-managed by a controller; remove subjects to disable."] [] "nil" [] ""} [{"Group" "rbac.authorization.k8s.io" "system:serviceaccounts:e2e-test-cli-deployment-cxnr9" ""}] {"rbac.authorization.k8s.io" "ClusterRole" "system:image-puller"
}} to be provisioned...                                
Apr 11 15:30:54.188: INFO: Waiting for RoleBinding {{"" ""} {"system:image-builders" "" "e2e-test-cli-deployment-cxnr9" "" "" "" '\x00' "0001-01-01 00:00:00 +0000 UTC" <nil> %!q(*int64=<nil>) map[] map["openshift.io/description":"Allows builds in this namespace to push im
ages to this namespace.  It is auto-managed by a controller; remove subjects to disable."] [] "nil" [] ""} [{"ServiceAccount" "" "builder" "e2e-test-cli-deployment-cxnr9"}] {"rbac.authorization.k8s.io" "ClusterRole" "system:image-builder"}} to be provisioned...
Apr 11 15:30:54.281: INFO: Waiting for RoleBinding {{"" ""} {"system:deployers" "" "e2e-test-cli-deployment-cxnr9" "" "" "" '\x00' "0001-01-01 00:00:00 +0000 UTC" <nil> %!q(*int64=<nil>) map[] map["openshift.io/description":"Allows deploymentconfigs in this namespace to r
ollout pods in this namespace.  It is auto-managed by a controller; remove subjects to disable."] [] "nil" [] ""} [{"ServiceAccount" "" "deployer" "e2e-test-cli-deployment-cxnr9"}] {"rbac.authorization.k8s.io" "ClusterRole" "system:deployer"}} to be provisioned...
Apr 11 15:30:54.376: INFO: Project "e2e-test-cli-deployment-cxnr9" has been fully provisioned.
[JustBeforeEach] [Feature:DeploymentConfig] deploymentconfigs                                                                  
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:45
[It] should run a deployment to completion and then scale to zero [Suite:openshift/conformance/parallel/minimal]               
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:327
Apr 11 15:30:54.529: INFO: created DC, creationTimestamp: 2019-04-11 15:30:54 +0800 CST
Apr 11 15:31:44.963: INFO: Latest rollout of dc/deployment-test (rc/deployment-test-1) is complete.                                                            
Apr 11 15:31:44.963: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 pod/deployment-test-1-deploy'
Apr 11 15:31:46.945: INFO: oc logs finished                       
Apr 11 15:31:46.945: INFO: verifying the deployment is marked complete and scaled to zero
Apr 11 15:31:47.616: INFO: Latest rollout of dc/deployment-test (rc/deployment-test-1) is complete.
Apr 11 15:31:47.616: INFO: checking the logs for substrings                                                                                                                                            
--> pre: Running hook pod ...                                                                                                                                                                         
test pre hook executed                                                                                                                                                                            
--> pre: Success                                                 
--> Scaling deployment-test-1 to 2                                                       
--> Success                                                                     
Apr 11 15:31:47.616: INFO: verifying that scaling does not result in new pods
Apr 11 15:31:47.616: INFO: Running 'oc scale --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 dc/deployment-test --replicas=1'
Apr 11 15:31:48.457: INFO: ensuring no scale up of the deployment happens
Apr 11 15:31:58.934: INFO: verifying the scale is updated on the deployment config
Apr 11 15:31:59.035: INFO: deploying a few more times                         
Apr 11 15:31:59.035: INFO: Running 'oc rollout --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 latest deployment-test'
Apr 11 15:31:59.949: INFO: waiting for the rollout #2 to finish                              
Apr 11 15:32:09.631: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 -f pods/deployment-test-2-deploy'
Apr 11 15:32:46.095: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 pod/deployment-test-2-deploy'
Apr 11 15:32:48.027: INFO: Latest rollout of dc/deployment-test (rc/deployment-test-2) is complete.
Apr 11 15:32:48.028: INFO: checking the logs for substrings                              
--> pre: Running hook pod ...
test pre hook executed
--> pre: Success
--> Scaling up deployment-test-2 from 0 to 1, scaling down deployment-test-1 from 0 to 0 (keep 1 pods available, don't exceed 2 pods)
    Scaling deployment-test-2 up to 1
--> Success
Apr 11 15:32:48.028: INFO: Running 'oc rollout --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 latest deployment-test'
Apr 11 15:32:48.743: INFO: waiting for the rollout #3 to finish
Apr 11 15:32:57.203: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 -f pods/deployment-test-3-deploy'
Apr 11 15:33:34.507: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 pod/deployment-test-3-deploy'
Apr 11 15:33:36.684: INFO: Latest rollout of dc/deployment-test (rc/deployment-test-3) is complete.
Apr 11 15:33:36.684: INFO: checking the logs for substrings
--> pre: Running hook pod ...
test pre hook executed
--> pre: Success
--> Scaling up deployment-test-3 from 0 to 1, scaling down deployment-test-2 from 0 to 0 (keep 1 pods available, don't exceed 2 pods)
    Scaling deployment-test-3 up to 1
--> Success
Apr 11 15:33:36.684: INFO: Running 'oc rollout --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 latest deployment-test'
Apr 11 15:33:38.794: INFO: waiting for the rollout #4 to finish
Apr 11 15:33:47.925: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 -f pods/deployment-test-4-deploy'
Apr 11 15:34:23.979: INFO: Running 'oc logs --config=/tmp/configfile028145405 --namespace=e2e-test-cli-deployment-cxnr9 pod/deployment-test-4-deploy'
Apr 11 15:34:26.013: INFO: Latest rollout of dc/deployment-test (rc/deployment-test-4) is complete.
Apr 11 15:34:26.013: INFO: checking the logs for substrings
--> pre: Running hook pod ...
test pre hook executed
--> pre: Success
--> Scaling up deployment-test-4 from 0 to 1, scaling down deployment-test-3 from 0 to 0 (keep 1 pods available, don't exceed 2 pods)
    Scaling deployment-test-4 up to 1
--> Success
[AfterEach] with test deployments [Conformance]
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:323
[AfterEach] [Feature:DeploymentConfig] deploymentconfigs
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/deployments/deployments.go:64
[AfterEach] [Feature:DeploymentConfig] deploymentconfigs
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/test/extended/util/cli.go:85
STEP: Deleting namespaces
Apr 11 15:34:28.724: INFO: namespace : e2e-test-cli-deployment-cxnr9 api call to delete is complete
STEP: Waiting for namespaces to vanish
[AfterEach] [Feature:DeploymentConfig] deploymentconfigs
  /home/wjiang/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:154
Apr 11 15:34:39.327: INFO: Waiting up to 3m0s for all (but 100) nodes to be ready
Apr 11 15:34:40.986: INFO: Running AfterSuite actions on all nodes
Apr 11 15:34:40.986: INFO: Running AfterSuite actions on node 1

Comment 7 errata-xmlrpc 2019-06-04 10:46:34 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:0758