kubernetes: Subtest junit parsing is fragile, indicates failures when stdout interleaves with go test output

test log output that interleaves go test output with server/background process stdout/stderr is not able to be parsed by the junit consumer, so the job thinks the test failed.

Examples: https://prow.k8s.io/view/gcs/kubernetes-jenkins/pr-logs/directory/pull-kubernetes-integration/1156611596072521728 thinks TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets/delete failed

Actual test output:

    --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets (0.13s)
        --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets/create (0.01s)
        --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets/update (0.01s)
        --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets/patch (0.02s)
        --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresI0731 17:25:00.892002  105320 controller.go:120] Shutting down OpenAPI controller
I0731 17:25:00.892209  105320 available_controller.go:389] Shutting down AvailableConditionController
I0731 17:25:00.892239  105320 apiapproval_controller.go:197] Shutting down KubernetesAPIApprovalPolicyConformantConditionController
I0731 17:25:00.892270  105320 nonstructuralschema_controller.go:203] Shutting down NonStructuralSchemaConditionController
I0731 17:25:00.892287  105320 establishing_controller.go:84] Shutting down EstablishingController
I0731 17:25:00.892305  105320 naming_controller.go:299] Shutting down NamingConditionController
I0731 17:25:00.892319  105320 customresource_discovery_controller.go:219] Shutting down DiscoveryController
I0731 17:25:00.892337  105320 crd_finalizer.go:267] Shutting down CRDFinalizer
I0731 17:25:00.892354  105320 crdregistration_controller.go:143] Shutting down crd-autoregister controller
I0731 17:25:00.892375  105320 autoregister_controller.go:164] Shutting down autoregister controller
I0731 17:25:00.892393  105320 apiservice_controller.go:106] Shutting down APIServiceRegistrationController
ets/delete (0.07s)
        --- PASS: TestWebhookV1beta1/settings.k8s.io.v1alpha1.podpresets/deletecollection (0.02s)

https://prow.k8s.io/view/gcs/kubernetes-jenkins/pr-logs/directory/pull-kubernetes-integration/1156611710002401280 thinks TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments failed

Actual test output:

    --- PASS: TestWebhooI0731 17:22:08.001746  104984 controller.go:87] Shutting down OpenAPI AggregationController
E0731 17:22:08.001828  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.PriorityClass: Get https://127.0.0.1:33041/apis/scheduling.k8s.io/v1/priorityclasses?allowWatchBookmarks=true&resourceVersion=2273&timeout=6m54s&timeoutSeconds=414&watch=true: unexpected EOF
E0731 17:22:08.001849  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.StorageClass: Get https://127.0.0.1:33041/apis/storage.k8s.io/v1/storageclasses?allowWatchBookmarks=true&resourceVersion=2430&timeout=6m4s&timeoutSeconds=364&watch=true: unexpected EOF
E0731 17:22:08.001875  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.Pod: Get https://127.0.0.1:33041/api/v1/pods?allowWatchBookmarks=true&resourceVersion=912&timeout=9m59s&timeoutSeconds=599&watch=true: unexpected EOF
E0731 17:22:08.001957  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.Service: Get https://127.0.0.1:33041/api/v1/services?allowWatchBookmarks=true&resourceVersion=1087&timeout=7m1s&timeoutSeconds=421&watch=true: unexpected EOF
E0731 17:22:08.001974  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.ServiceAccount: Get https://127.0.0.1:33041/api/v1/serviceaccounts?allowWatchBookmarks=true&resourceVersion=1067&timeout=9m31s&timeoutSeconds=571&watch=true: unexpected EOF
E0731 17:22:08.001998  104984 reflector.go:282] k8s.io/kube-aggregator/pkg/client/informers/externalversions/factory.go:117: Failed to watch *v1.APIService: Get https://127.0.0.1:33041/apis/apiregistration.k8s.io/v1/apiservices?allowWatchBookmarks=true&resourceVersion=1228&timeout=9m42s&timeoutSeconds=582&watch=true: unexpected EOF
E0731 17:22:08.002017  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.LimitRange: Get https://127.0.0.1:33041/api/v1/limitranges?allowWatchBookmarks=true&resourceVersion=809&timeout=6m20s&timeoutSeconds=380&watch=true: unexpected EOF
E0731 17:22:08.002037  104984 reflector.go:282] k8s.io/apiextensions-apiserver/pkg/client/informers/internalversion/factory.go:117: Failed to watch *apiextensions.CustomResourceDefinition: Get https://127.0.0.1:33041/apis/apiextensions.k8s.io/v1beta1/customresourcedefinitions?allowWatchBookmarks=true&resourceVersion=1180&timeout=6m12s&timeoutSeconds=372&watch=true: unexpected EOF
E0731 17:22:08.002062  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.Namespace: Get https://127.0.0.1:33041/api/v1/namespaces?allowWatchBookmarks=true&resourceVersion=824&timeout=6m44s&timeoutSeconds=404&watch=true: unexpected EOF
E0731 17:22:08.002079  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.Endpoints: Get https://127.0.0.1:33041/api/v1/endpoints?allowWatchBookmarks=true&resourceVersion=780&timeout=6m43s&timeoutSeconds=403&watch=true: unexpected EOF
E0731 17:22:08.002113  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1beta1.ValidatingWebhookConfiguration: Get https://127.0.0.1:33041/apis/admissionregistration.k8s.io/v1beta1/validatingwebhookconfigurations?allowWatchBookmarks=true&resourceVersion=1140&timeout=8m1s&timeoutSeconds=481&watch=true: unexpected EOF
E0731 17:22:08.002128  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.Secret: Get https://127.0.0.1:33041/api/v1/secrets?allowWatchBookmarks=true&resourceVersion=1053&timeout=7m50s&timeoutSeconds=470&watch=true: unexpected EOF
E0731 17:22:08.002166  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1beta1.MutatingWebhookConfiguration: Get https://127.0.0.1:33041/apis/admissionregistration.k8s.io/v1beta1/mutatingwebhookconfigurations?allowWatchBookmarks=true&resourceVersion=1127&timeout=7m6s&timeoutSeconds=426&watch=true: unexpected EOF
E0731 17:22:08.002202  104984 reflector.go:282] k8s.io/client-go/informers/factory.go:133: Failed to watch *v1.ResourceQuota: Get https://127.0.0.1:33041/api/v1/resourcequotas?allowWatchBookmarks=true&resourceVersion=1038&timeout=7m53s&timeoutSeconds=473&watch=true: unexpected EOF
I0731 17:22:08.002484  104984 controller.go:176] Shutting down kubernetes service endpoint reconciler
I0731 17:22:08.002547  104984 secure_serving.go:160] Stopped listening on 127.0.0.1:33041
E0731 17:22:08.024786  104984 controller.go:179] Get https://127.0.0.1:33041/api/v1/namespaces/default/endpoints/kubernetes: dial tcp 127.0.0.1:33041: connect: connection refused
kV1beta1/storage.k8s.io.v1beta1.volumeattachments (0.11s)
        --- PASS: TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments/create (0.01s)
        --- PASS: TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments/update (0.01s)
        --- PASS: TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments/patch (0.01s)
        --- PASS: TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments/delete (0.05s)
        --- PASS: TestWebhookV1beta1/storage.k8s.io.v1beta1.volumeattachments/deletecollection (0.03s)

note how in both cases, server output is entangled with test results

it is possible that tests using subtests are more vulnerable to parsing errors (the go test output junit parsing is quite fragile)

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Comments: 21 (21 by maintainers)

Most upvoted comments

I’m throwing together a quick test to see how easy it is to switch to that

we are not, and we should.

Thanks for the heads up, we’ll take a look