[Fail] [sig-storage] In-tree Volumes [Driver: nfs] [BeforeEach] [Testpattern: Dynamic PV (default fs)] provisioning should provision storage with defaults

Driver が NFS の場合、失敗している。 xfs、gluster、csi-hostpath-v0 など他のドライバの場合は非サポートとしてテストがスキップされている。

失敗時のログ

ESC[0m[sig-storage] In-tree VolumesESC[0m ESC[90m[Driver: nfs]ESC[0m ESC[0m[Testpattern: Dynamic PV (default fs)] provisioningESC[0m
  ESC[1mshould provision storage with defaultsESC[0m
  ESC[37m/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/provisioning.go:176ESC[0m
[BeforeEach] [sig-storage] In-tree Volumes
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:153
ESC[1mSTEPESC[0m: Creating a kubernetes client
Jan  7 20:24:48.175: INFO: >>> kubeConfig: /home/ubuntu/admin.conf
ESC[1mSTEPESC[0m: Building a namespace api object, basename volumes
ESC[1mSTEPESC[0m: Waiting for a default service account to be provisioned in namespace
[BeforeEach] [sig-storage] In-tree Volumes
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/in_tree_volumes.go:68
[BeforeEach] [Driver: nfs]
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/in_tree_volumes.go:81
Jan  7 20:24:48.349: INFO: Unexpected error occurred: 0-length response
...
[sig-storage] In-tree Volumes
ESC[90m/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/utils/framework.go:22ESC[0m
  [Driver: nfs]
  ESC[90m/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/in_tree_volumes.go:78ESC[0m
    ESC[91mESC[1m[Testpattern: Dynamic PV (default fs)] provisioning [BeforeEach]ESC[0m
    ESC[90m/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/provisioning.go:104ESC[0m
      should provision storage with defaults
      ESC[90m/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/testsuites/provisioning.go:176ESC[0m

      ESC[91mFailed to update authorization: 0-length response
      Expected error:
          <*errors.errorString | 0xc000d08260>: {
              s: "0-length response",
          }
          0-length response
      not to have occurredESC[0m

      /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/storage/drivers/in_tree.go:155

test/e2e/storage/drivers/in_tree.go

 152         err := framework.WaitForAuthorizationUpdate(cs.AuthorizationV1beta1(),
 153                 serviceaccount.MakeUsername(ns.Name, "default"),
 154                 "", "get", schema.GroupResource{Group: "storage.k8s.io", Resource: "storageclasses"}, true)
 155         framework.ExpectNoError(err, "Failed to update authorization: %v", err)

test/e2e/framework/authorizer_util.go

 39 // WaitForAuthorizationUpdate checks if the given user can perform the named verb and action.
 40 // If policyCachePollTimeout is reached without the expected condition matching, an error is returned
 41 func WaitForAuthorizationUpdate(c v1beta1authorization.SubjectAccessReviewsGetter, user, namespace, verb string, resource schema.GroupResource, allowed b    ool) error {
 42         return WaitForNamedAuthorizationUpdate(c, user, namespace, verb, "", resource, allowed)
 43 }
...
 47 func WaitForNamedAuthorizationUpdate(c v1beta1authorization.SubjectAccessReviewsGetter, user, namespace, verb, resourceName string, resource schema.Group    Resource, allowed bool) error {
 48         review := &authorizationv1beta1.SubjectAccessReview{
 49                 Spec: authorizationv1beta1.SubjectAccessReviewSpec{
 50                         ResourceAttributes: &authorizationv1beta1.ResourceAttributes{
 51                                 Group:     resource.Group,
 52                                 Verb:      verb,
 53                                 Resource:  resource.Resource,
 54                                 Namespace: namespace,
 55                                 Name:      resourceName,
 56                         },
 57                         User: user,
 58                 },
 59         }
 60         err := wait.Poll(policyCachePollInterval, policyCachePollTimeout, func() (bool, error) {
 61                 response, err := c.SubjectAccessReviews().Create(review)
 62                 // GKE doesn't enable the SAR endpoint.  Without this endpoint, we cannot determine if the policy engine
 63                 // has adjusted as expected.  In this case, simply wait one second and hope it's up to date
 64                 if apierrors.IsNotFound(err) {
 65                         klog.Info("SubjectAccessReview endpoint is missing")
 66                         time.Sleep(1 * time.Second)
 67                         return true, nil
 68                 }
 69                 if err != nil {
 70                         return false, err
 71                 }
 72                 if response.Status.Allowed != allowed {
 73                         return false, nil
 74                 }
 75                 return true, nil
 76         })
 77         return err
 78 }

vendor/k8s.io/client-go/rest/request.go

1091 // Into stores the result into obj, if possible. If obj is nil it is ignored.
1092 // If the returned object is of type Status and has .Status != StatusSuccess, the
1093 // additional information in Status will be used to enrich the error.
1094 func (r Result) Into(obj runtime.Object) error {
1095         if r.err != nil {
1096                 // Check whether the result has a Status object in the body and prefer that.
1097                 return r.Error()
1098         }
1099         if r.decoder == nil {
1100                 return fmt.Errorf("serializer for %s doesn't exist", r.contentType)
1101         }
1102         if len(r.body) == 0 {
1103                 return fmt.Errorf("0-length response")
1104         }
1105
1106         out, _, err := r.decoder.Decode(r.body, nil, obj)
1107         if err != nil || out == obj {
1108                 return err
1109         }
1110         // if a different object is returned, see if it is Status and avoid double decoding
1111         // the object.
1112         switch t := out.(type) {
1113         case *metav1.Status:
1114                 // any status besides StatusSuccess is considered an error.
1115                 if t.Status != metav1.StatusSuccess {
1116                         return errors.FromObject(t)
1117                 }
1118         }
1119         return nil
1120 }

https://github.com/kubernetes/client-go/commit/00496caa6af765b6b9b2bdf4ba9948a5fabe4635 で詳細を出すようになった。 flake しているため。k/kubernetes/issues/71696

ローカル環境も必ず起きるものではなさそう。現時点で 1/5 の確率。flake?

https://gubernator.k8s.io/build/kubernetes-jenkins/pr-logs/pull/72698/pull-kubernetes-integration/40647/ を分析

apiserver_test.go:334: 0-length response with status code: 200 and content type:

./test/integration/examples/apiserver_test.go

319         _, err = aggregatorClient.ApiregistrationV1beta1().APIServices().Create(&apiregistrationv1beta1.APIService{
320                 ObjectMeta: metav1.ObjectMeta{Name: "v1alpha1.wardle.k8s.io"},
321                 Spec: apiregistrationv1beta1.APIServiceSpec{
322                         Service: &apiregistrationv1beta1.ServiceReference{
323                                 Namespace: "kube-wardle",
324                                 Name:      "api",
325                         },
326                         Group:                "wardle.k8s.io",
327                         Version:              "v1alpha1",
328                         CABundle:             wardleCA,
329                         GroupPriorityMinimum: 200,
330                         VersionPriority:      200,
331                 },
332         })
333         if err != nil {
334                 t.Fatal(err)
335         }

APIServiceの作成処理で 0-length エラーになっている模様。ちなみに e2e ではなく integration テスト

ついでに unit、integration、e2e の分類わけを勉強。

https://testing.googleblog.com/2015/04/just-say-no-to-more-end-to-end-tests.html

unit: 単体テスト、関数レベルでの動作をテストする integration: 統合テスト、複数の unit（関数）を組合わせた状態でテストする e2e: End-to-Endテスト、全体を組み合わせ、APIの振舞いをテストする

Google 的には Unit、Integration、e2e のテスト割合が 70%、20%、10%になることが理想らしい。

https://github.com/oomichi/try-kubernetes/wiki/%E6%84%8F%E8%A8%B3%EF%BC%9A%E3%80%8C-Just-Say-No-to-More-End-to-End-Tests-%E3%80%8D に記載

Community CI で Integration テストが落ちる事象は未だ起きている。 https://gubernator.k8s.io/build/kubernetes-jenkins/pr-logs/pull/72769/pull-kubernetes-integration/40853/

I0110 18:39:00.839643  124499 wrap.go:47] GET /api/v1/namespaces/default/endpoints/kubernetes: (7.282393ms) 200 [volume.test/v0.0.0 (linux/amd64) kubernetes/$Format 127.0.0.1:36982]
I0110 18:39:00.842947  124499 wrap.go:47] PUT /api/v1/namespaces/default/endpoints/kubernetes: (2.66501ms) 200 [volume.test/v0.0.0 (linux/amd64) kubernetes/$Format 127.0.0.1:36982]
attach_detach_test.go:166: Failed to created node : 0-length response with status code: 200 and content type:

./test/integration/volume/attach_detach_test.go

165         if _, err := testClient.Core().Nodes().Create(node); err != nil {
166                 t.Fatalf("Failed to created node : %v", err)
167         }

client-go/kubernetes/typed/core/v1/node.go

106 // Create takes the representation of a node and creates it.  Returns the server's representation of the node, and an error, if there is any.
107 func (c *nodes) Create(node *v1.Node) (result *v1.Node, err error) {
108         result = &v1.Node{}
109         err = c.client.Post().
110                 Resource("nodes").
111                 Body(node).
112                 Do().
113                 Into(result)
114         return
115 }

https://kubernetes.io/docs/reference/generated/kubernetes-api/v1.10/#create-494 によると、"create a node" APIでは常にResponse BodyとしてNodeオブジェクトを返すので、クライアント側で Into() でデシリアライズするのは正しい。問題はAPIサーバ側がちゃんとResponse Bodyを返しているかどうか。

Integration Testの場合のAPIサーバのデプロイ方法は？対象の Integration test を解析する。 test/integration/volume/attach_detach_test.go

142 // Via integration test we can verify that if pod delete
143 // event is somehow missed by AttachDetach controller - it still
144 // gets cleaned up by Desired State of World populator.

Integration Testを通して、我々は「Podが削除されたイベントがAttachDetach Controllerに見逃された場合でも、それはDesired State of World populatorによってクリーンアップされること」を確かめる。

145 func TestPodDeletionWithDswp(t *testing.T) {
146         _, server, closeFn := framework.RunAMaster(framework.NewIntegrationTestMasterConfig())

Integration Test用にMasterを起動

147         defer closeFn()
148         namespaceName := "test-pod-deletion"
149         node := &v1.Node{
150                 ObjectMeta: metav1.ObjectMeta{
151                         Name: "node-sandbox",
152                         Annotations: map[string]string{
153                                 util.ControllerManagedAttachAnnotation: "true",
154                         },
155                 },
156         }
157
158         ns := framework.CreateTestingNamespace(namespaceName, server, t)
159         defer framework.DeleteTestingNamespace(ns, server, t)

Test用Namespaceを作成

160
161         testClient, ctrl, _, informers := createAdClients(ns, t, server, defaultSyncPeriod, defaultTimerConfig)
162         pod := fakePodWithVol(namespaceName)
163         podStopCh := make(chan struct{})
164
165         if _, err := testClient.Core().Nodes().Create(node); err != nil {
166                 t.Fatalf("Failed to created node : %v", err)

node-sandboxという名前でnode作成を実施 ★ここでエラーになった。

Integration Test向けAPI サーバのコードを調査 master_utils.go

338 func RunAMaster(masterConfig *master.Config) (*master.Master, *httptest.Server, CloseFunc) {
339         if masterConfig == nil {
340                 masterConfig = NewMasterConfig()
341                 masterConfig.GenericConfig.EnableProfiling = true
342         }
343         return startMasterOrDie(masterConfig, nil, nil)
344 }

master_utils.go

112 // startMasterOrDie starts a kubernetes master and an httpserver to handle api requests
113 func startMasterOrDie(masterConfig *master.Config, incomingServer *httptest.Server, masterReceiver MasterReceiver) (*master.Master, *httptest.Server, CloseFunc) {
114         var m *master.Master
115         var s *httptest.Server
116
117         // Ensure we log at least level 4
118         v := flag.Lookup("v").Value
119         level, _ := strconv.Atoi(v.String())
120         if level < 4 {
121                 v.Set("4")
122         }
123
124         if incomingServer != nil {
125                 s = incomingServer
126         } else {
127                 s = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
128                         m.GenericAPIServer.Handler.ServeHTTP(w, req)
129                 }))

incomingServerはnilなのでNewServerで作成

130         }
131
132         stopCh := make(chan struct{})
133         closeFn := func() {
134                 m.GenericAPIServer.RunPreShutdownHooks()
135                 close(stopCh)
136                 s.Close()
137         }
138
139         if masterConfig == nil {
140                 masterConfig = NewMasterConfig()
141                 masterConfig.GenericConfig.OpenAPIConfig = genericapiserver.DefaultOpenAPIConfig(openapi.GetOpenAPIDefinitions, openapinamer.NewDefinitionNamer(legacyscheme.Scheme))
142                 masterConfig.GenericConfig.OpenAPIConfig.Info = &spec.Info{
143                         InfoProps: spec.InfoProps{
144                                 Title:   "Kubernetes",
145                                 Version: "unversioned",
146                         },
147                 }
148                 masterConfig.GenericConfig.OpenAPIConfig.DefaultResponse = &spec.Response{
149                         ResponseProps: spec.ResponseProps{
150                                 Description: "Default Response.",
151                         },
152                 }
153                 masterConfig.GenericConfig.OpenAPIConfig.GetDefinitions = openapi.GetOpenAPIDefinitions
154                 masterConfig.GenericConfig.SwaggerConfig = genericapiserver.DefaultSwaggerConfig()
155         }
156
157         // set the loopback client config
158         if masterConfig.GenericConfig.LoopbackClientConfig == nil {
159                 masterConfig.GenericConfig.LoopbackClientConfig = &restclient.Config{QPS: 50, Burst: 100, ContentConfig: restclient.ContentConfig{NegotiatedSerializer: legacyscheme.Code    cs}}
160         }
161         masterConfig.GenericConfig.LoopbackClientConfig.Host = s.URL
162
163         privilegedLoopbackToken := uuid.NewRandom().String()
164         // wrap any available authorizer
165         tokens := make(map[string]*user.DefaultInfo)
166         tokens[privilegedLoopbackToken] = &user.DefaultInfo{
167                 Name:   user.APIServerUser,
168                 UID:    uuid.NewRandom().String(),
169                 Groups: []string{user.SystemPrivilegedGroup},
170         }
171
172         tokenAuthenticator := authenticatorfactory.NewFromTokens(tokens)
173         if masterConfig.GenericConfig.Authentication.Authenticator == nil {
174                 masterConfig.GenericConfig.Authentication.Authenticator = authenticatorunion.New(tokenAuthenticator, authauthenticator.RequestFunc(alwaysEmpty))
175         } else {
176                 masterConfig.GenericConfig.Authentication.Authenticator = authenticatorunion.New(tokenAuthenticator, masterConfig.GenericConfig.Authentication.Authenticator)
177         }
178
179         if masterConfig.GenericConfig.Authorization.Authorizer != nil {
180                 tokenAuthorizer := authorizerfactory.NewPrivilegedGroups(user.SystemPrivilegedGroup)
181                 masterConfig.GenericConfig.Authorization.Authorizer = authorizerunion.New(tokenAuthorizer, masterConfig.GenericConfig.Authorization.Authorizer)
182         } else {
183                 masterConfig.GenericConfig.Authorization.Authorizer = alwaysAllow{}
184         }
185
186         masterConfig.GenericConfig.LoopbackClientConfig.BearerToken = privilegedLoopbackToken
187
188         clientset, err := clientset.NewForConfig(masterConfig.GenericConfig.LoopbackClientConfig)
189         if err != nil {
190                 klog.Fatal(err)
191         }
192
193         masterConfig.ExtraConfig.VersionedInformers = informers.NewSharedInformerFactory(clientset, masterConfig.GenericConfig.LoopbackClientConfig.Timeout)
194         m, err = masterConfig.Complete().New(genericapiserver.NewEmptyDelegate())
195         if err != nil {
196                 closeFn()
197                 klog.Fatalf("error in bringing up the master: %v", err)
198         }
199         if masterReceiver != nil {
200                 masterReceiver.SetMaster(m)
201         }
202
203         // TODO have this start method actually use the normal start sequence for the API server
204         // this method never actually calls the `Run` method for the API server
205         // fire the post hooks ourselves
206         m.GenericAPIServer.PrepareRun()
207         m.GenericAPIServer.RunPostStartHooks(stopCh)
208
209         cfg := *masterConfig.GenericConfig.LoopbackClientConfig
210         cfg.ContentConfig.GroupVersion = &schema.GroupVersion{}
211         privilegedClient, err := restclient.RESTClientFor(&cfg)
212         if err != nil {
213                 closeFn()
214                 klog.Fatal(err)
215         }
216         var lastHealthContent []byte
217         err = wait.PollImmediate(100*time.Millisecond, 30*time.Second, func() (bool, error) {
218                 result := privilegedClient.Get().AbsPath("/healthz").Do()
219                 status := 0
220                 result.StatusCode(&status)
221                 if status == 200 {
222                         return true, nil
223                 }
224                 lastHealthContent, _ = result.Raw()
225                 return false, nil
226         })
227         if err != nil {
228                 closeFn()
229                 klog.Errorf("last health content: %q", string(lastHealthContent))
230                 klog.Fatal(err)
231         }
232
233         return m, s, closeFn
234 }

k/kubernetes/issues/71696#issuecomment-451493696

k//kubernetes/pull/72498

http responseがhttp status 0 だった場合、Traceback を生成する。何かが誤っていることをすぐに検知するため

上記のPRマージ後もTracebackが生成されることは無かったため、本問題は無い。 DefaultのGoサーバがそれを 0-length response with 200 status code として処理するため。これがサーバログに status code 0 が出力され、client 側では 0-length の 200 status code と見えてしまう原因だ。

サーバ側で対象になりそうなコードは https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/status.go#L42

何で内部でエラーになった処理をHTTP200系に変換するのか良くわからない・・呼出元の一つ。コメント「もしもオリジナルのStatusCodeが成功ではない場合、オリジナルのエラーをそのまま返す必要がある。ネゴシエーションの問題を隠すことはできないので」今回の問題ではオリジナルのStatusCodeが成功のようなので（上記のL42を通ることから）、コメントからするとネゴシエーションの問題で成功のように見せかけて返しているけど、Bodyを設定していないのでクライアントでエラーになっている？

125 // WriteObjectNegotiated renders an object in the content type negotiated by the client.
126 // The context is optional and can be nil.
127 func WriteObjectNegotiated(s runtime.NegotiatedSerializer, gv schema.GroupVersion, w http.ResponseWriter, req *http.Request, statusCode int, object runti    me.Object) {
128         serializer, err := negotiation.NegotiateOutputSerializer(req, s)
129         if err != nil {
130                 // if original statusCode was not successful we need to return the original error
131                 // we cannot hide it behind negotiation problems
132                 if statusCode < http.StatusOK || statusCode >= http.StatusBadRequest {
133                         WriteRawJSON(int(statusCode), object, w)
134                         return
135                 }
136                 status := ErrorToAPIStatus(err)
137                 WriteRawJSON(int(status.Code), status, w)
138                 return
139         }
140
141         if ae := request.AuditEventFrom(req.Context()); ae != nil {
142                 audit.LogResponseObject(ae, object, gv, s)
143         }
144
145         encoder := s.EncoderForVersion(serializer.Serializer, gv)
146         SerializeObject(serializer.MediaType, encoder, w, req, statusCode, object)
147 }

k/kubernetes/pull/72650 で liggitt さんもこのコードを疑ってデバッグ処理を追加している。

NegotiateOutputSerializer() がエラーになるケースを調べる。 NegotiateOutputSerializerはResponse をシリアライズする際にmedia type に合わせてシリアライザーを選ぶ処理 apiserver/pkg/endpoints/handlers/negotiation/negotiate.go

 43 // NegotiateOutputMediaType negotiates the output structured media type and a serializer, or
 44 // returns an error.
 45 func NegotiateOutputMediaType(req *http.Request, ns runtime.NegotiatedSerializer, restrictions EndpointRestrictions) (MediaTypeOptions, runtime.Serialize    rInfo, error) {
 46         mediaType, ok := NegotiateMediaTypeOptions(req.Header.Get("Accept"), AcceptedMediaTypesForEndpoint(ns), restrictions)
 47         if !ok {
 48                 supported, _ := MediaTypesForSerializer(ns)
 49                 return mediaType, runtime.SerializerInfo{}, NewNotAcceptableError(supported)
 50         }
 51         // TODO: move into resthandler
 52         info := mediaType.Accepted.Serializer
 53         if (mediaType.Pretty || isPrettyPrint(req)) && info.PrettySerializer != nil {
 54                 info.Serializer = info.PrettySerializer
 55         }
 56         return mediaType, info, nil
 57 }
 58
 59 // NegotiateOutputSerializer returns a serializer for the output.
 60 func NegotiateOutputSerializer(req *http.Request, ns runtime.NegotiatedSerializer) (runtime.SerializerInfo, error) {
 61         _, info, err := NegotiateOutputMediaType(req, ns, DefaultEndpointRestrictions)
 62         return info, err
 63 }

つまり

 48                 supported, _ := MediaTypesForSerializer(ns)
 49                 return mediaType, runtime.SerializerInfo{}, NewNotAcceptableError(supported)

の NewNotAcceptableError(supported) にあたるところが err として ErrorToAPIStatus() に渡される。

そもそも MediaTypeを選ぶ処理が変に見える。 line 285で「適切なMedia typeが見つからなかったとして、空とfalse を返す」となっているが、そもそも accepted が1以上あるのであれば、line 261 のようにとりあえずデフォルトの json を返せばよいのでは？ header の長さが0のときだけ通るようにしている理由がわからない。 → line 265以降はheaderの情報を頼りに適切なcontent type を得ようとしているため。 → それが失敗した場合の考慮が無いのでは？ → apiserver自体、長い間触られていない・・　あまりメンテナンスされていないように見える apiserver/pkg/endpoints/handlers/negotiation/negotiate.go

256 // NegotiateMediaTypeOptions returns the most appropriate content type given the accept header and
257 // a list of alternatives along with the accepted media type parameters.
258 func NegotiateMediaTypeOptions(header string, accepted []AcceptedMediaType, endpoint EndpointRestrictions) (MediaTypeOptions, bool) {
259         if len(header) == 0 && len(accepted) > 0 {
260                 return MediaTypeOptions{
261                         Accepted: &accepted[0],
262                 }, true
263         }
264
265         var candidates candidateMediaTypeSlice
266         clauses := goautoneg.ParseAccept(header)
267         for _, clause := range clauses {
268                 for i := range accepted {
269                         accepts := &accepted[i]
270                         switch {
271                         case clause.Type == accepts.Type && clause.SubType == accepts.SubType,
272                                 clause.Type == accepts.Type && clause.SubType == "*",
273                                 clause.Type == "*" && clause.SubType == "*":
274                                 candidates = append(candidates, candidateMediaType{accepted: accepts, clauses: clause})
275                         }
276                 }
277         }
278
279         for _, v := range candidates {
280                 if retVal, ret := acceptMediaTypeOptions(v.clauses.Params, v.accepted, endpoint); ret {
281                         return retVal, true
282                 }
283         }
284
285         return MediaTypeOptions{}, false
286 }

upstream で close した。

oomichi / try-kubernetes

[Fail] [sig-storage] In-tree Volumes [Driver: nfs] [BeforeEach] [Testpattern: Dynamic PV (default fs)] provisioning should provision storage with defaults #73