Skip to content
This repository has been archived by the owner on Jun 7, 2021. It is now read-only.

Volumes get created but mounting fails #23

Closed
jprukner opened this issue May 6, 2019 · 14 comments
Closed

Volumes get created but mounting fails #23

jprukner opened this issue May 6, 2019 · 14 comments

Comments

@jprukner
Copy link

jprukner commented May 6, 2019 •
edited
Loading

Hey, I am having a trouble with csi-packet. Volumes get created but mounting fails.
Could you please point me how to debug this issue? @deitch
State after kubectl apply -f demo-deployment.yaml:

root@master:~/csi-packet/deploy/kubernetes# kubectl describe pod nginx-5f47999bdc-j7bf2 
Name:               nginx-5f47999bdc-j7bf2
Namespace:          demo
Priority:           0
PriorityClassName:  <none>
Node:               master/10.100.127.1
Start Time:         Mon, 06 May 2019 14:48:58 +0000
Labels:             pod-template-hash=5f47999bdc
                    run=nginx
...
Volumes:
  mypvc:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  podpvc
    ReadOnly:   false
  default-token-lfrxw:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  default-token-lfrxw
    Optional:    false
QoS Class:       BestEffort
Node-Selectors:  <none>
Tolerations:     node.kubernetes.io/not-ready:NoExecute for 300s
                 node.kubernetes.io/unreachable:NoExecute for 300s
Events:
  Type     Reason                  Age                    From                     Message
  ----     ------                  ----                   ----                     -------
  Warning  FailedScheduling        5m29s (x3 over 5m30s)  default-scheduler        pod has unbound immediate PersistentVolumeClaims
  Normal   Scheduled               5m26s                  default-scheduler        Successfully assigned demo/nginx-5f47999bdc-j7bf2 to master
  Normal   SuccessfulAttachVolume  5m25s                  attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
  Warning  FailedMount             67s (x2 over 3m23s)    kubelet, master          Unable to mount volumes for pod "nginx-5f47999bdc-j7bf2_demo(11ebdca2-700e-11e9-8581-0cc47ab58a7a)": timeout expired waiting for volumes to attach or mount for pod "demo"/"nginx-5f47999bdc-j7bf2". list of unmounted volumes=[mypvc]. list of unattached volumes=[mypvc default-token-lfrxw]
  Warning  FailedMount             60s (x9 over 5m8s)     kubelet, master          MountVolume.MountDevice failed for volume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

root@master:~/csi-packet/deploy/kubernetes# systemctl | grep running | grep csi
iscsid.service                                                                                                                                        loaded active running   iSCSI initiator daemon (iscsid)                                                                                      
iscsid.socket                                                                                                                                         loaded active running   Open-iSCSI iscsid Socket

root@master:~/csi-packet/deploy/kubernetes# systemctl | grep running | grep multipath
multipathd.service                                                                                                                                    loaded active running   Device-Mapper Multipath Device Controller  

root@master:~/csi-packet/deploy/kubernetes# cat /etc/multipath.conf
defaults {
        user_friendly_names yes
}

Logs

Logs of csi-node

root@master:~/csi-packet/deploy/kubernetes# kubectl -n kube-system logs csi-node-qgpp2 packet-driver 
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"Starting server","node":"master","time":"2019-05-06T14:46:02Z"}
{"address":"//csi/csi.sock","level":"info","msg":"Listening for connections","proto":"unix","time":"2019-05-06T14:46:02Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T14:47:02Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T14:47:02Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetInfo called","node":"master","time":"2019-05-06T14:47:02Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetInfo","GRPC.request":"","level":"info","msg":"GRPC response: node_id:\"master\" ","time":"2019-05-06T14:47:02Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetInfo called","node":"master","time":"2019-05-06T14:47:02Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetInfo","GRPC.request":"","level":"info","msg":"GRPC response: node_id:\"master\" ","time":"2019-05-06T14:47:02Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:47:36Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:47:36Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:47:36Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:49:01Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:49:01Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:49:01Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:49:17Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:49:17Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:49:17Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:49:33Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:49:33Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:49:33Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:49:50Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:49:50Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:49:50Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:50:09Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:50:09Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:50:09Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:50:32Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:50:32Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:50:32Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:51:03Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:51:03Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:51:03Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:51:50Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:51:50Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:51:50Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:53:09Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:53:09Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:53:09Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:55:27Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:55:27Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:55:27Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T14:57:44Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T14:57:44Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T14:57:44Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeGetCapabilities called","node":"master","time":"2019-05-06T15:00:01Z"}
{"GRPC.call":"/csi.v1.Node/NodeGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:STAGE_UNSTAGE_VOLUME \u003e \u003e ","time":"2019-05-06T15:00:01Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"NodeStageVolume called","node":"master","time":"2019-05-06T15:00:01Z"}

root@master:~/csi-packet/deploy/kubernetes# kubectl -n kube-system logs csi-node-qgpp2 csi-driver-registrar 
I0506 14:46:02.105073       1 main.go:111] Version: v1.0.1-0-g27703026
I0506 14:46:02.105306       1 main.go:118] Attempting to open a gRPC connection with: "/csi/csi.sock"
I0506 14:46:02.105343       1 connection.go:69] Connecting to /csi/csi.sock
I0506 14:46:02.106675       1 connection.go:96] Still trying, connection is TRANSIENT_FAILURE
I0506 14:46:03.106575       1 connection.go:96] Still trying, connection is CONNECTING
I0506 14:47:02.105870       1 connection.go:89] Connection timed out
I0506 14:47:02.105932       1 main.go:126] Calling CSI driver to discover driver name.
I0506 14:47:02.106141       1 connection.go:137] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 14:47:02.106187       1 connection.go:138] GRPC request: {}
I0506 14:47:02.112521       1 connection.go:140] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 14:47:02.114677       1 connection.go:141] GRPC error: <nil>
I0506 14:47:02.114713       1 main.go:134] CSI driver name: "net.packet.csi"
I0506 14:47:02.114807       1 main.go:138] Loading kubeconfig.
I0506 14:47:02.117013       1 node_register.go:55] Calling CSI driver to discover node ID.
I0506 14:47:02.117092       1 connection.go:137] GRPC call: /csi.v1.Node/NodeGetInfo
I0506 14:47:02.117127       1 connection.go:138] GRPC request: {}
I0506 14:47:02.122155       1 connection.go:140] GRPC response: {"node_id":"master"}
I0506 14:47:02.124004       1 connection.go:141] GRPC error: <nil>
I0506 14:47:02.124039       1 node_register.go:63] CSI driver node ID: "master"
I0506 14:47:02.125012       1 node_register.go:86] Starting Registration Server at: /registration/net.packet.csi-reg.sock
I0506 14:47:02.125295       1 node_register.go:93] Registration Server started at: /registration/net.packet.csi-reg.sock
I0506 14:47:02.167380       1 main.go:84] Received GetInfo call: &InfoRequest{}
I0506 14:47:02.209852       1 main.go:94] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:true,Error:,}

Logs of csi-packet-controller

root@master:~/csi-packet/deploy/kubernetes# kubectl -n kube-system logs csi-packet-controller-0 csi-attacher
I0506 11:59:03.798729       1 main.go:76] Version: v1.0.1-0-gb7dadac
I0506 11:59:03.816895       1 connection.go:89] Connecting to /csi/csi.sock
I0506 11:59:03.818888       1 connection.go:116] Still trying, connection is CONNECTING
I0506 11:59:03.822912       1 connection.go:116] Still trying, connection is TRANSIENT_FAILURE
I0506 11:59:04.819986       1 connection.go:116] Still trying, connection is TRANSIENT_FAILURE
I0506 11:59:05.861559       1 connection.go:116] Still trying, connection is CONNECTING
I0506 11:59:05.862247       1 connection.go:113] Connected
I0506 11:59:05.862355       1 connection.go:242] GRPC call: /csi.v1.Identity/Probe
I0506 11:59:05.862393       1 connection.go:243] GRPC request: {}
I0506 11:59:05.872390       1 connection.go:245] GRPC response: {}
I0506 11:59:05.874439       1 connection.go:246] GRPC error: <nil>
I0506 11:59:05.874473       1 main.go:211] Probe succeeded
I0506 11:59:05.874540       1 connection.go:242] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 11:59:05.874576       1 connection.go:243] GRPC request: {}
I0506 11:59:05.878599       1 connection.go:245] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 11:59:05.880436       1 connection.go:246] GRPC error: <nil>
I0506 11:59:05.880475       1 main.go:128] CSI driver name: "net.packet.csi"
I0506 11:59:05.880511       1 connection.go:242] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 11:59:05.880666       1 connection.go:243] GRPC request: {}
I0506 11:59:05.884493       1 connection.go:245] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 11:59:05.888291       1 connection.go:246] GRPC error: <nil>
I0506 11:59:05.888328       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 11:59:05.888651       1 connection.go:243] GRPC request: {}
I0506 11:59:05.892440       1 connection.go:245] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 11:59:05.902541       1 connection.go:246] GRPC error: <nil>
I0506 11:59:05.902656       1 main.go:152] CSI driver supports ControllerPublishUnpublish, using real CSI handler
I0506 11:59:05.903399       1 controller.go:111] Starting CSI attacher
I0506 11:59:07.578749       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:07.579246       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:07.579591       1 csi_handler.go:422] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 11:59:07.596728       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:07.596797       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:07.596838       1 csi_handler.go:422] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 11:59:08.757986       1 controller.go:173] Started VA processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.758196       1 csi_handler.go:93] CSIHandler: processing VA "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.758292       1 csi_handler.go:120] Attaching "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.758375       1 csi_handler.go:259] Starting attach operation for "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.758601       1 csi_handler.go:220] Adding finalizer to PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:08.778034       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:08.778096       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:08.778137       1 csi_handler.go:422] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 11:59:08.778807       1 csi_handler.go:228] PV finalizer added to "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:08.782208       1 csi_handler.go:524] Can't get CSINodeInfo master: csinodeinfos.csi.storage.k8s.io "master" is forbidden: User "system:serviceaccount:kube-system:csi-controller-sa" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I0506 11:59:08.782878       1 csi_handler.go:181] VA finalizer added to "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.783734       1 csi_handler.go:195] NodeID annotation added to "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:08.798396       1 csi_handler.go:205] VolumeAttachment "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c" updated with finalizer and/or NodeID annotation
I0506 11:59:08.798586       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0506 11:59:08.798721       1 connection.go:243] GRPC request: {"node_id":"master","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1557143943332-8081-net.packet.csi"},"volume_id":"ff8ec137-7021-4504-a79f-bbc058e4b08d"}
I0506 11:59:11.444582       1 connection.go:245] GRPC response: {"publish_context":{"AttachmentId":"36756f50-82d1-447e-9da8-0f7925d98931","VolumeId":"ff8ec137-7021-4504-a79f-bbc058e4b08d","VolumeName":"volume-ff8ec137"}}
I0506 11:59:11.446771       1 connection.go:246] GRPC error: <nil>
I0506 11:59:11.446814       1 csi_handler.go:133] Attached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.446855       1 util.go:33] Marking as attached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.456876       1 util.go:43] Marked as attached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.456936       1 csi_handler.go:139] Fully attached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.456979       1 csi_handler.go:109] CSIHandler: finished processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.457069       1 controller.go:173] Started VA processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.457132       1 csi_handler.go:93] CSIHandler: processing VA "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 11:59:11.457177       1 csi_handler.go:115] "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c" is already attached
I0506 11:59:11.457217       1 csi_handler.go:109] CSIHandler: finished processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.183584       1 controller.go:173] Started VA processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.183666       1 csi_handler.go:93] CSIHandler: processing VA "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.183706       1 csi_handler.go:144] Starting detach operation for "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.183841       1 csi_handler.go:151] Detaching "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.187813       1 csi_handler.go:524] Can't get CSINodeInfo master: csinodeinfos.csi.storage.k8s.io "master" is forbidden: User "system:serviceaccount:kube-system:csi-controller-sa" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I0506 12:04:44.187989       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerUnpublishVolume
I0506 12:04:44.188080       1 connection.go:243] GRPC request: {"node_id":"master","volume_id":"ff8ec137-7021-4504-a79f-bbc058e4b08d"}
I0506 12:04:44.746999       1 connection.go:245] GRPC response: {}
I0506 12:04:44.748949       1 connection.go:246] GRPC error: <nil>
I0506 12:04:44.748987       1 csi_handler.go:377] Detached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.749141       1 util.go:71] Marking as detached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.759412       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:04:44.759475       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:04:44.759516       1 csi_handler.go:422] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 12:04:44.762106       1 util.go:82] Finalizer removed from "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.762171       1 csi_handler.go:164] Fully detached "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:04:44.762215       1 csi_handler.go:109] CSIHandler: finished processing "csi-db9123764bb8e66ed733d79f037e8d3cc05be81df00500018d4f71be36604d2c"
I0506 12:05:09.406242       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:09.406462       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:09.406665       1 csi_handler.go:422] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 12:05:11.203823       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:11.205872       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:11.206704       1 csi_handler.go:460] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
I0506 12:05:11.226347       1 csi_handler.go:481] Removed finalizer from PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:11.226511       1 controller.go:203] Started PV processing "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:11.226592       1 csi_handler.go:418] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 12:05:11.226701       1 csi_handler.go:438] CSIHandler: processing PV "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": no finalizer, ignoring
I0506 13:36:03.515540       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.517184       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.519623       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:36:03.522266       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.522340       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.522385       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:36:03.534757       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.534817       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.534857       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:36:05.086512       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.086579       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.086619       1 csi_handler.go:120] Attaching "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.086656       1 csi_handler.go:259] Starting attach operation for "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.086825       1 csi_handler.go:220] Adding finalizer to PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:05.096748       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:05.096909       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:05.096974       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:36:05.098034       1 csi_handler.go:228] PV finalizer added to "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:05.100131       1 csi_handler.go:524] Can't get CSINodeInfo master: csinodeinfos.csi.storage.k8s.io "master" is forbidden: User "system:serviceaccount:kube-system:csi-controller-sa" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope
I0506 13:36:05.100387       1 csi_handler.go:181] VA finalizer added to "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.100452       1 csi_handler.go:195] NodeID annotation added to "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:05.109752       1 csi_handler.go:205] VolumeAttachment "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" updated with finalizer and/or NodeID annotation
I0506 13:36:05.109834       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0506 13:36:05.109911       1 connection.go:243] GRPC request: {"node_id":"master","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":5}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1557143943332-8081-net.packet.csi"},"volume_id":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c"}
I0506 13:36:06.581420       1 connection.go:245] GRPC response: {"publish_context":{"AttachmentId":"3b4c118f-4602-4b8f-b7d5-9fb42b81a503","VolumeId":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c","VolumeName":"volume-22be26ad"}}
I0506 13:36:06.584023       1 connection.go:246] GRPC error: <nil>
I0506 13:36:06.584142       1 csi_handler.go:133] Attached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.584455       1 util.go:33] Marking as attached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.598641       1 util.go:43] Marked as attached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.598713       1 csi_handler.go:139] Fully attached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.604486       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.604777       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.604830       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:36:06.604900       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 13:36:06.604983       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:39:05.972277       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:39:05.972355       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:39:05.972396       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 13:39:05.972436       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:39:05.974285       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:39:05.974345       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:39:05.974385       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:49:05.972715       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:49:05.972804       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:49:05.972845       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 13:49:05.972886       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:49:05.974554       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:49:05.974626       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:49:05.974670       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 13:59:05.972942       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:59:05.973022       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:59:05.973064       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 13:59:05.973150       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 13:59:05.974741       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:59:05.974800       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:59:05.974840       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:09:05.973181       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:09:05.973271       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:09:05.973353       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 14:09:05.973443       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:09:05.975064       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:09:05.975125       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:09:05.975168       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:19:05.973525       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:19:05.973607       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:19:05.973649       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 14:19:05.974010       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:19:05.975230       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:19:05.975302       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:19:05.975346       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:29:05.973737       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:29:05.973810       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:29:05.973852       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 14:29:05.973892       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:29:05.975456       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:29:05.975525       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:29:05.975569       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:36:31.502899       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.502974       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.503018       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:36:31.518042       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.519522       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.519703       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:36:31.538222       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.538306       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.538351       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:36:33.921371       1 controller.go:173] Started VA processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.921443       1 csi_handler.go:93] CSIHandler: processing VA "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.921788       1 csi_handler.go:120] Attaching "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.921828       1 csi_handler.go:259] Starting attach operation for "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.922033       1 csi_handler.go:220] Adding finalizer to PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:33.931573       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:33.932268       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:33.932777       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:36:33.935903       1 csi_handler.go:228] PV finalizer added to "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:33.938880       1 csi_handler.go:524] Can't get CSINodeInfo master: the server could not find the requested resource (get csinodeinfos.csi.storage.k8s.io master)
I0506 14:36:33.939306       1 csi_handler.go:181] VA finalizer added to "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.939368       1 csi_handler.go:195] NodeID annotation added to "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:33.949532       1 csi_handler.go:205] VolumeAttachment "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da" updated with finalizer and/or NodeID annotation
I0506 14:36:33.949701       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0506 14:36:33.949735       1 connection.go:243] GRPC request: {"node_id":"master","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1557143943332-8081-net.packet.csi"},"volume_id":"5b8c530a-11fd-419c-a559-b27860d06a10"}
I0506 14:36:35.723455       1 connection.go:245] GRPC response: {"publish_context":{"AttachmentId":"9131360a-7109-4e9a-bead-14c4adb79da6","VolumeId":"5b8c530a-11fd-419c-a559-b27860d06a10","VolumeName":"volume-5b8c530a"}}
I0506 14:36:35.725279       1 connection.go:246] GRPC error: <nil>
I0506 14:36:35.725318       1 csi_handler.go:133] Attached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.725359       1 util.go:33] Marking as attached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736540       1 util.go:43] Marked as attached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736604       1 csi_handler.go:139] Fully attached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736649       1 csi_handler.go:109] CSIHandler: finished processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736722       1 controller.go:173] Started VA processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736770       1 csi_handler.go:93] CSIHandler: processing VA "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:36:35.736810       1 csi_handler.go:115] "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da" is already attached
I0506 14:36:35.736855       1 csi_handler.go:109] CSIHandler: finished processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:39:05.974046       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:39:05.974117       1 controller.go:173] Started VA processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:39:05.974177       1 csi_handler.go:93] CSIHandler: processing VA "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:39:05.974219       1 csi_handler.go:115] "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da" is already attached
I0506 14:39:05.974288       1 csi_handler.go:109] CSIHandler: finished processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:39:05.974121       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:39:05.974434       1 csi_handler.go:115] "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110" is already attached
I0506 14:39:05.974476       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:39:05.975835       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:39:05.975998       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:39:05.976157       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:39:05.975902       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:39:05.976292       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:39:05.976455       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:46:58.869716       1 controller.go:173] Started VA processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:58.869792       1 csi_handler.go:93] CSIHandler: processing VA "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:58.869877       1 csi_handler.go:144] Starting detach operation for "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:58.870115       1 csi_handler.go:151] Detaching "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:58.874052       1 csi_handler.go:524] Can't get CSINodeInfo master: the server could not find the requested resource (get csinodeinfos.csi.storage.k8s.io master)
I0506 14:46:58.874816       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerUnpublishVolume
I0506 14:46:58.874908       1 connection.go:243] GRPC request: {"node_id":"master","volume_id":"5b8c530a-11fd-419c-a559-b27860d06a10"}
I0506 14:46:59.708603       1 connection.go:245] GRPC response: {}
I0506 14:46:59.711927       1 connection.go:246] GRPC error: <nil>
I0506 14:46:59.711968       1 csi_handler.go:377] Detached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:59.712216       1 util.go:71] Marking as detached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:59.724599       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:46:59.725082       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:46:59.725139       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:46:59.728535       1 util.go:82] Finalizer removed from "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:59.728624       1 csi_handler.go:164] Fully detached "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:46:59.728669       1 csi_handler.go:109] CSIHandler: finished processing "csi-31e6a09d5752fbf54aa1c7c39c7398e9b2edbab37c97794f07b5596862a1b8da"
I0506 14:47:00.634477       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:00.634539       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:00.634580       1 csi_handler.go:422] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:47:02.638247       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.638600       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.639535       1 csi_handler.go:460] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
E0506 14:47:02.664467       1 csi_handler.go:477] Failed to remove finalizer from PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": Operation cannot be fulfilled on persistentvolumes "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": the object has been modified; please apply your changes to the latest version and try again
I0506 14:47:02.664819       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.664975       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.665224       1 csi_handler.go:460] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
I0506 14:47:02.687757       1 csi_handler.go:481] Removed finalizer from PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.687906       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.687985       1 csi_handler.go:418] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.688233       1 csi_handler.go:460] CSIHandler: processing PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
E0506 14:47:02.694454       1 csi_handler.go:477] Failed to remove finalizer from PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": Operation cannot be fulfilled on persistentvolumes "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": StorageError: invalid object, Code: 4, Key: /registry/persistentvolumes/pvc-56600899-700c-11e9-8581-0cc47ab58a7a, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: 571bfcfe-700c-11e9-8581-0cc47ab58a7a, UID in object meta: 
I0506 14:47:02.699817       1 controller.go:203] Started PV processing "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:47:02.699897       1 controller.go:210] PV "pvc-56600899-700c-11e9-8581-0cc47ab58a7a" deleted, ignoring
I0506 14:48:18.902885       1 controller.go:173] Started VA processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:18.902963       1 csi_handler.go:93] CSIHandler: processing VA "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:18.903613       1 csi_handler.go:144] Starting detach operation for "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:18.903930       1 csi_handler.go:151] Detaching "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:18.909114       1 csi_handler.go:524] Can't get CSINodeInfo master: the server could not find the requested resource (get csinodeinfos.csi.storage.k8s.io master)
I0506 14:48:18.909430       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerUnpublishVolume
I0506 14:48:18.909528       1 connection.go:243] GRPC request: {"node_id":"master","volume_id":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c"}
I0506 14:48:19.363971       1 connection.go:245] GRPC response: {}
I0506 14:48:19.365918       1 connection.go:246] GRPC error: <nil>
I0506 14:48:19.365958       1 csi_handler.go:377] Detached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:19.366069       1 util.go:71] Marking as detached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:19.377232       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:19.377297       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:19.377338       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:19.378178       1 util.go:82] Finalizer removed from "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:19.378241       1 csi_handler.go:164] Fully detached "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:19.378283       1 csi_handler.go:109] CSIHandler: finished processing "csi-6f159cb39f15889bb92ce1e27a6d789336390a853b10facbf703507154182110"
I0506 14:48:32.566530       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:32.566655       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:32.566697       1 csi_handler.go:422] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:34.745795       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.745859       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.745986       1 csi_handler.go:460] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
E0506 14:48:34.760096       1 csi_handler.go:477] Failed to remove finalizer from PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": Operation cannot be fulfilled on persistentvolumes "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": the object has been modified; please apply your changes to the latest version and try again
I0506 14:48:34.760450       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.760700       1 csi_handler.go:418] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.761683       1 csi_handler.go:460] CSIHandler: processing PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": no VA found, removing finalizer
I0506 14:48:34.773323       1 csi_handler.go:481] Removed finalizer from PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.773434       1 controller.go:203] Started PV processing "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 14:48:34.773812       1 controller.go:210] PV "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a" deleted, ignoring
I0506 14:48:55.900391       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.900564       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.900681       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:55.915064       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.915136       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.915177       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:55.925638       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.925732       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.925773       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:58.100505       1 controller.go:173] Started VA processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.100581       1 csi_handler.go:93] CSIHandler: processing VA "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.100621       1 csi_handler.go:120] Attaching "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.100659       1 csi_handler.go:259] Starting attach operation for "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.100846       1 csi_handler.go:220] Adding finalizer to PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:58.111692       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:58.111767       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:58.111808       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:48:58.120017       1 csi_handler.go:228] PV finalizer added to "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:58.125079       1 csi_handler.go:524] Can't get CSINodeInfo master: the server could not find the requested resource (get csinodeinfos.csi.storage.k8s.io master)
I0506 14:48:58.125422       1 csi_handler.go:181] VA finalizer added to "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.125731       1 csi_handler.go:195] NodeID annotation added to "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:58.145336       1 csi_handler.go:205] VolumeAttachment "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369" updated with finalizer and/or NodeID annotation
I0506 14:48:58.145411       1 connection.go:242] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0506 14:48:58.145444       1 connection.go:243] GRPC request: {"node_id":"master","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"storage.kubernetes.io/csiProvisionerIdentity":"1557143943332-8081-net.packet.csi"},"volume_id":"bfd30da9-4229-4b65-934a-1c79ebbb9267"}
I0506 14:48:59.885364       1 connection.go:245] GRPC response: {"publish_context":{"AttachmentId":"d6b5a14a-6363-443f-b4b2-25d3003d9b4e","VolumeId":"bfd30da9-4229-4b65-934a-1c79ebbb9267","VolumeName":"volume-bfd30da9"}}
I0506 14:48:59.887531       1 connection.go:246] GRPC error: <nil>
I0506 14:48:59.887571       1 csi_handler.go:133] Attached "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.887612       1 util.go:33] Marking as attached "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.900903       1 util.go:43] Marked as attached "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.900967       1 csi_handler.go:139] Fully attached "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.901011       1 csi_handler.go:109] CSIHandler: finished processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.901201       1 controller.go:173] Started VA processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.901261       1 csi_handler.go:93] CSIHandler: processing VA "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:48:59.901302       1 csi_handler.go:115] "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369" is already attached
I0506 14:48:59.901343       1 csi_handler.go:109] CSIHandler: finished processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:49:05.974385       1 controller.go:173] Started VA processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:49:05.974449       1 csi_handler.go:93] CSIHandler: processing VA "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:49:05.974490       1 csi_handler.go:115] "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369" is already attached
I0506 14:49:05.974530       1 csi_handler.go:109] CSIHandler: finished processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:49:05.976008       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:49:05.976053       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:49:05.976093       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring
I0506 14:59:05.974662       1 controller.go:173] Started VA processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:59:05.974730       1 csi_handler.go:93] CSIHandler: processing VA "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:59:05.975120       1 csi_handler.go:115] "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369" is already attached
I0506 14:59:05.975176       1 csi_handler.go:109] CSIHandler: finished processing "csi-80c78e99068f7c26fd44a10688ad124e41a22cc0e1496f72fe8a31333278f369"
I0506 14:59:05.977391       1 controller.go:203] Started PV processing "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:59:05.977735       1 csi_handler.go:418] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:59:05.978101       1 csi_handler.go:422] CSIHandler: processing PV "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a": no deletion timestamp, ignoring

root@master:~/csi-packet/deploy/kubernetes# kubectl -n kube-system logs csi-packet-controller-0 csi-external-provisioner
I0506 11:59:03.282208       1 csi-provisioner.go:82] Version: v1.0.1-0-g9a258a0a
I0506 11:59:03.282413       1 csi-provisioner.go:96] Building kube configs for running in cluster...
I0506 11:59:03.332423       1 controller.go:197] Connecting to /csi/csi.sock
I0506 11:59:03.334188       1 controller.go:224] Still trying, connection is CONNECTING
I0506 11:59:03.335618       1 controller.go:224] Still trying, connection is TRANSIENT_FAILURE
I0506 11:59:04.337503       1 controller.go:224] Still trying, connection is TRANSIENT_FAILURE
I0506 11:59:05.226744       1 controller.go:224] Still trying, connection is CONNECTING
I0506 11:59:05.227180       1 controller.go:224] Still trying, connection is TRANSIENT_FAILURE
I0506 11:59:06.035137       1 controller.go:224] Still trying, connection is CONNECTING
I0506 11:59:06.041844       1 controller.go:221] Connected
I0506 11:59:06.044887       1 controller.go:571] Starting provisioner controller net.packet.csi_csi-packet-controller-0_592f5644-6ff6-11e9-9daf-ae4278b78cf5!
I0506 11:59:06.145269       1 controller.go:620] Started provisioner controller net.packet.csi_csi-packet-controller-0_592f5644-6ff6-11e9-9daf-ae4278b78cf5!
I0506 11:59:06.145748       1 controller.go:926] provision "default/podpvc" class "csi-packet-standard": started
I0506 11:59:06.152623       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 11:59:06.153139       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"podpvc", UID:"7ca5470a-6ff4-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"21997", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/podpvc"
I0506 11:59:06.152672       1 controller.go:189] GRPC request: {}
I0506 11:59:06.165787       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 11:59:06.170531       1 controller.go:192] GRPC error: <nil>
I0506 11:59:06.170579       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 11:59:06.170610       1 controller.go:189] GRPC request: {}
I0506 11:59:06.174541       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 11:59:06.181434       1 controller.go:192] GRPC error: <nil>
I0506 11:59:06.181795       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 11:59:06.181834       1 controller.go:189] GRPC request: {}
I0506 11:59:06.185608       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 11:59:06.187560       1 controller.go:192] GRPC error: <nil>
I0506 11:59:06.187887       1 controller.go:544] CreateVolumeRequest {Name:pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[plan:standard] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 11:59:06.188379       1 controller.go:188] GRPC call: /csi.v1.Controller/CreateVolume
I0506 11:59:06.188416       1 controller.go:189] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a","parameters":{"plan":"standard"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0506 11:59:07.529435       1 controller.go:191] GRPC response: {"volume":{"capacity_bytes":10737418240,"volume_id":"ff8ec137-7021-4504-a79f-bbc058e4b08d"}}
I0506 11:59:07.532856       1 controller.go:192] GRPC error: <nil>
I0506 11:59:07.533063       1 controller.go:605] create volume rep: {CapacityBytes:10737418240 VolumeId:ff8ec137-7021-4504-a79f-bbc058e4b08d VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 11:59:07.533279       1 controller.go:666] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:net.packet.csi,VolumeHandle:ff8ec137-7021-4504-a79f-bbc058e4b08d,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{storage.kubernetes.io/csiProvisionerIdentity: 1557143943332-8081-net.packet.csi,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:nil,}}
I0506 11:59:07.536639       1 controller.go:1026] provision "default/podpvc" class "csi-packet-standard": volume "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a" provisioned
I0506 11:59:07.536721       1 controller.go:1040] provision "default/podpvc" class "csi-packet-standard": trying to save persistentvolume "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"
I0506 11:59:07.594791       1 controller.go:1047] provision "default/podpvc" class "csi-packet-standard": persistentvolume "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a" saved
I0506 11:59:07.594928       1 controller.go:1088] provision "default/podpvc" class "csi-packet-standard": succeeded
I0506 11:59:07.595025       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"podpvc", UID:"7ca5470a-6ff4-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"21997", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a
I0506 12:05:09.405522       1 controller.go:1097] delete "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": started
I0506 12:05:09.414038       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 12:05:09.414093       1 controller.go:189] GRPC request: {}
I0506 12:05:09.416807       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 12:05:09.419761       1 controller.go:192] GRPC error: <nil>
I0506 12:05:09.419809       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 12:05:09.419839       1 controller.go:189] GRPC request: {}
I0506 12:05:09.422670       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 12:05:09.428346       1 controller.go:192] GRPC error: <nil>
I0506 12:05:09.428412       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 12:05:09.428443       1 controller.go:189] GRPC request: {}
I0506 12:05:09.431364       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 12:05:09.433196       1 controller.go:192] GRPC error: <nil>
I0506 12:05:09.442474       1 controller.go:188] GRPC call: /csi.v1.Controller/DeleteVolume
I0506 12:05:09.442527       1 controller.go:189] GRPC request: {"volume_id":"ff8ec137-7021-4504-a79f-bbc058e4b08d"}
I0506 12:05:11.190303       1 controller.go:191] GRPC response: {}
I0506 12:05:11.193847       1 controller.go:192] GRPC error: <nil>
I0506 12:05:11.194016       1 controller.go:1125] delete "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": volume deleted
I0506 12:05:11.212344       1 controller.go:1135] delete "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": persistentvolume deleted
I0506 12:05:11.212869       1 controller.go:1137] delete "pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a": succeeded
I0506 13:36:02.588526       1 controller.go:926] provision "demo/mycluster" class "csi-packet-performance": started
I0506 13:36:02.605503       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 13:36:02.605617       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"mycluster", UID:"de8fa832-7003-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"30266", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "demo/mycluster"
I0506 13:36:02.605550       1 controller.go:189] GRPC request: {}
I0506 13:36:02.608500       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 13:36:02.612479       1 controller.go:192] GRPC error: <nil>
I0506 13:36:02.612647       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 13:36:02.612794       1 controller.go:189] GRPC request: {}
I0506 13:36:02.617016       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 13:36:02.623495       1 controller.go:192] GRPC error: <nil>
I0506 13:36:02.623550       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 13:36:02.623580       1 controller.go:189] GRPC request: {}
I0506 13:36:02.626950       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 13:36:02.628730       1 controller.go:192] GRPC error: <nil>
I0506 13:36:02.628792       1 controller.go:544] CreateVolumeRequest {Name:pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a CapacityRange:required_bytes:1000000000  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:MULTI_NODE_MULTI_WRITER > ] Parameters:map[plan:performance] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 13:36:02.629001       1 controller.go:188] GRPC call: /csi.v1.Controller/CreateVolume
I0506 13:36:02.629034       1 controller.go:189] GRPC request: {"capacity_range":{"required_bytes":1000000000},"name":"pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a","parameters":{"plan":"performance"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":5}}]}
I0506 13:36:03.497186       1 controller.go:191] GRPC response: {"volume":{"capacity_bytes":10737418240,"volume_id":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c"}}
I0506 13:36:03.500863       1 controller.go:192] GRPC error: <nil>
I0506 13:36:03.500943       1 controller.go:605] create volume rep: {CapacityBytes:10737418240 VolumeId:22be26ad-6c16-4d8f-9d06-d8117b8a4c8c VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 13:36:03.501160       1 controller.go:666] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:net.packet.csi,VolumeHandle:22be26ad-6c16-4d8f-9d06-d8117b8a4c8c,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{storage.kubernetes.io/csiProvisionerIdentity: 1557143943332-8081-net.packet.csi,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:nil,}}
I0506 13:36:03.501496       1 controller.go:1026] provision "demo/mycluster" class "csi-packet-performance": volume "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a" provisioned
I0506 13:36:03.501818       1 controller.go:1040] provision "demo/mycluster" class "csi-packet-performance": trying to save persistentvolume "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"
I0506 13:36:03.519581       1 controller.go:1047] provision "demo/mycluster" class "csi-packet-performance": persistentvolume "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a" saved
I0506 13:36:03.520273       1 controller.go:1088] provision "demo/mycluster" class "csi-packet-performance": succeeded
I0506 13:36:03.520498       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"mycluster", UID:"de8fa832-7003-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"30266", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a
I0506 14:36:30.279937       1 controller.go:926] provision "demo/podpvc" class "csi-packet-standard": started
I0506 14:36:30.295591       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 14:36:30.295730       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"podpvc", UID:"56600899-700c-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"34758", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "demo/podpvc"
I0506 14:36:30.296051       1 controller.go:189] GRPC request: {}
I0506 14:36:30.307989       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 14:36:30.315019       1 controller.go:192] GRPC error: <nil>
I0506 14:36:30.315072       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 14:36:30.315103       1 controller.go:189] GRPC request: {}
I0506 14:36:30.323741       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 14:36:30.334252       1 controller.go:192] GRPC error: <nil>
I0506 14:36:30.334327       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 14:36:30.334371       1 controller.go:189] GRPC request: {}
I0506 14:36:30.340160       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 14:36:30.347861       1 controller.go:192] GRPC error: <nil>
I0506 14:36:30.348372       1 controller.go:544] CreateVolumeRequest {Name:pvc-56600899-700c-11e9-8581-0cc47ab58a7a CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[plan:standard] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 14:36:30.348862       1 controller.go:188] GRPC call: /csi.v1.Controller/CreateVolume
I0506 14:36:30.349394       1 controller.go:189] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-56600899-700c-11e9-8581-0cc47ab58a7a","parameters":{"plan":"standard"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0506 14:36:31.482124       1 controller.go:191] GRPC response: {"volume":{"capacity_bytes":10737418240,"volume_id":"5b8c530a-11fd-419c-a559-b27860d06a10"}}
I0506 14:36:31.485184       1 controller.go:192] GRPC error: <nil>
I0506 14:36:31.485240       1 controller.go:605] create volume rep: {CapacityBytes:10737418240 VolumeId:5b8c530a-11fd-419c-a559-b27860d06a10 VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 14:36:31.485580       1 controller.go:666] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:net.packet.csi,VolumeHandle:5b8c530a-11fd-419c-a559-b27860d06a10,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{storage.kubernetes.io/csiProvisionerIdentity: 1557143943332-8081-net.packet.csi,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:nil,}}
I0506 14:36:31.485825       1 controller.go:1026] provision "demo/podpvc" class "csi-packet-standard": volume "pvc-56600899-700c-11e9-8581-0cc47ab58a7a" provisioned
I0506 14:36:31.486010       1 controller.go:1040] provision "demo/podpvc" class "csi-packet-standard": trying to save persistentvolume "pvc-56600899-700c-11e9-8581-0cc47ab58a7a"
I0506 14:36:31.504682       1 controller.go:1047] provision "demo/podpvc" class "csi-packet-standard": persistentvolume "pvc-56600899-700c-11e9-8581-0cc47ab58a7a" saved
I0506 14:36:31.504889       1 controller.go:1088] provision "demo/podpvc" class "csi-packet-standard": succeeded
I0506 14:36:31.504995       1 controller.go:926] provision "demo/podpvc" class "csi-packet-standard": started
I0506 14:36:31.506251       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"podpvc", UID:"56600899-700c-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"34758", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pvc-56600899-700c-11e9-8581-0cc47ab58a7a
I0506 14:36:31.524461       1 controller.go:935] provision "demo/podpvc" class "csi-packet-standard": persistentvolume "pvc-56600899-700c-11e9-8581-0cc47ab58a7a" already exists, skipping
I0506 14:47:00.634848       1 controller.go:1097] delete "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": started
I0506 14:47:00.646245       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 14:47:00.646935       1 controller.go:189] GRPC request: {}
I0506 14:47:00.653932       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 14:47:00.659676       1 controller.go:192] GRPC error: <nil>
I0506 14:47:00.659727       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 14:47:00.659758       1 controller.go:189] GRPC request: {}
I0506 14:47:00.663392       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 14:47:00.669916       1 controller.go:192] GRPC error: <nil>
I0506 14:47:00.669970       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 14:47:00.670000       1 controller.go:189] GRPC request: {}
I0506 14:47:00.672755       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 14:47:00.674548       1 controller.go:192] GRPC error: <nil>
I0506 14:47:00.680290       1 controller.go:188] GRPC call: /csi.v1.Controller/DeleteVolume
I0506 14:47:00.680340       1 controller.go:189] GRPC request: {"volume_id":"5b8c530a-11fd-419c-a559-b27860d06a10"}
I0506 14:47:02.626682       1 controller.go:191] GRPC response: {}
I0506 14:47:02.628824       1 controller.go:192] GRPC error: <nil>
I0506 14:47:02.628872       1 controller.go:1125] delete "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": volume deleted
I0506 14:47:02.658367       1 controller.go:1135] delete "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": persistentvolume deleted
I0506 14:47:02.658436       1 controller.go:1137] delete "pvc-56600899-700c-11e9-8581-0cc47ab58a7a": succeeded
I0506 14:48:32.563370       1 controller.go:1097] delete "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": started
I0506 14:48:32.572714       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 14:48:32.572765       1 controller.go:189] GRPC request: {}
I0506 14:48:32.575794       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 14:48:32.578622       1 controller.go:192] GRPC error: <nil>
I0506 14:48:32.578669       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 14:48:32.578699       1 controller.go:189] GRPC request: {}
I0506 14:48:32.581742       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 14:48:32.587309       1 controller.go:192] GRPC error: <nil>
I0506 14:48:32.587364       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 14:48:32.587395       1 controller.go:189] GRPC request: {}
I0506 14:48:32.590308       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 14:48:32.591816       1 controller.go:192] GRPC error: <nil>
I0506 14:48:32.597871       1 controller.go:188] GRPC call: /csi.v1.Controller/DeleteVolume
I0506 14:48:32.598128       1 controller.go:189] GRPC request: {"volume_id":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c"}
I0506 14:48:34.733408       1 controller.go:191] GRPC response: {}
I0506 14:48:34.734860       1 controller.go:192] GRPC error: <nil>
I0506 14:48:34.734908       1 controller.go:1125] delete "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": volume deleted
I0506 14:48:34.744621       1 controller.go:1135] delete "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": persistentvolume deleted
I0506 14:48:34.744678       1 controller.go:1137] delete "pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a": succeeded
I0506 14:48:54.367635       1 controller.go:926] provision "demo/podpvc" class "csi-packet-standard": started
I0506 14:48:54.407234       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0506 14:48:54.410387       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"podpvc", UID:"11e21ced-700e-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"35784", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "demo/podpvc"
I0506 14:48:54.407299       1 controller.go:189] GRPC request: {}
I0506 14:48:54.457363       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I0506 14:48:54.460664       1 controller.go:192] GRPC error: <nil>
I0506 14:48:54.460717       1 controller.go:188] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0506 14:48:54.460747       1 controller.go:189] GRPC request: {}
I0506 14:48:54.464008       1 controller.go:191] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":3}}}]}
I0506 14:48:54.471247       1 controller.go:192] GRPC error: <nil>
I0506 14:48:54.471330       1 controller.go:188] GRPC call: /csi.v1.Identity/GetPluginInfo
I0506 14:48:54.471362       1 controller.go:189] GRPC request: {}
I0506 14:48:54.474589       1 controller.go:191] GRPC response: {"name":"net.packet.csi","vendor_version":"UNKNOWN"}
I0506 14:48:54.476061       1 controller.go:192] GRPC error: <nil>
I0506 14:48:54.476124       1 controller.go:544] CreateVolumeRequest {Name:pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a CapacityRange:required_bytes:1073741824  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[plan:standard] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 14:48:54.476362       1 controller.go:188] GRPC call: /csi.v1.Controller/CreateVolume
I0506 14:48:54.476416       1 controller.go:189] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a","parameters":{"plan":"standard"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0506 14:48:55.887057       1 controller.go:191] GRPC response: {"volume":{"capacity_bytes":10737418240,"volume_id":"bfd30da9-4229-4b65-934a-1c79ebbb9267"}}
I0506 14:48:55.892611       1 controller.go:192] GRPC error: <nil>
I0506 14:48:55.892670       1 controller.go:605] create volume rep: {CapacityBytes:10737418240 VolumeId:bfd30da9-4229-4b65-934a-1c79ebbb9267 VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0506 14:48:55.892857       1 controller.go:666] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:net.packet.csi,VolumeHandle:bfd30da9-4229-4b65-934a-1c79ebbb9267,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{storage.kubernetes.io/csiProvisionerIdentity: 1557143943332-8081-net.packet.csi,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:nil,}}
I0506 14:48:55.893125       1 controller.go:1026] provision "demo/podpvc" class "csi-packet-standard": volume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a" provisioned
I0506 14:48:55.893205       1 controller.go:1040] provision "demo/podpvc" class "csi-packet-standard": trying to save persistentvolume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"
I0506 14:48:55.916601       1 controller.go:1047] provision "demo/podpvc" class "csi-packet-standard": persistentvolume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a" saved
I0506 14:48:55.916944       1 controller.go:1088] provision "demo/podpvc" class "csi-packet-standard": succeeded
I0506 14:48:55.917220       1 controller.go:926] provision "demo/podpvc" class "csi-packet-standard": started
I0506 14:48:55.920388       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"demo", Name:"podpvc", UID:"11e21ced-700e-11e9-8581-0cc47ab58a7a", APIVersion:"v1", ResourceVersion:"35784", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a
I0506 14:48:55.928362       1 controller.go:935] provision "demo/podpvc" class "csi-packet-standard": persistentvolume "pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a" already exists, skipping

root@master:~/csi-packet/deploy/kubernetes# kubectl -n kube-system logs csi-packet-controller-0 packet-driver 
{"level":"info","msg":"Creating provider","project_id":"2fd10789-77c0-4138-9d6c-d7e8c7a81ed2","time":"2019-05-06T11:59:04Z"}
{"facility_id":"e1e9c52e-a0bc-4117-b996-0fc94843ea09","level":"info","msg":"facility found","project_id":"2fd10789-77c0-4138-9d6c-d7e8c7a81ed2","time":"2019-05-06T11:59:05Z"}
{"endpoint":"unix:///csi/csi.sock","level":"info","msg":"Starting server","node":"master","time":"2019-05-06T11:59:05Z"}
{"address":"//csi/csi.sock","level":"info","msg":"Listening for connections","proto":"unix","time":"2019-05-06T11:59:05Z"}
{"level":"info","msg":"PacketIdentityServer.Probe called with args: \u0026csi.ProbeRequest{XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}","time":"2019-05-06T11:59:05Z"}
{"GRPC.call":"/csi.v1.Identity/Probe","GRPC.request":"","level":"info","msg":"GRPC response: ","time":"2019-05-06T11:59:05Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T11:59:05Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T11:59:05Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T11:59:05Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T11:59:05Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T11:59:05Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T11:59:06Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T11:59:06Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T11:59:06Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T11:59:06Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T11:59:06Z"}
{"level":"info","msg":"CreateVolume called","time":"2019-05-06T11:59:06Z","volume_name":"pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"}
{"level":"info","msg":"Volume requested","planID":"87728148-3155-4992-a730-8d1e6aca8a32","sizeRequestGiB":10,"time":"2019-05-06T11:59:06Z","volume_name":"pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a"}
{"GRPC.call":"/csi.v1.Controller/CreateVolume","GRPC.request":"name:\"pvc-7ca5470a-6ff4-11e9-8581-0cc47ab58a7a\" capacity_range:\u003crequired_bytes:1073741824 \u003e volume_capabilities:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e parameters:\u003ckey:\"plan\" value:\"standard\" \u003e ","level":"info","msg":"GRPC response: volume:\u003ccapacity_bytes:10737418240 volume_id:\"ff8ec137-7021-4504-a79f-bbc058e4b08d\" \u003e ","time":"2019-05-06T11:59:07Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerPublishVolume","GRPC.request":"volume_id:\"ff8ec137-7021-4504-a79f-bbc058e4b08d\" node_id:\"master\" volume_capability:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e volume_context:\u003ckey:\"storage.kubernetes.io/csiProvisionerIdentity\" value:\"1557143943332-8081-net.packet.csi\" \u003e ","level":"info","msg":"GRPC response: publish_context:\u003ckey:\"AttachmentId\" value:\"36756f50-82d1-447e-9da8-0f7925d98931\" \u003e publish_context:\u003ckey:\"VolumeId\" value:\"ff8ec137-7021-4504-a79f-bbc058e4b08d\" \u003e publish_context:\u003ckey:\"VolumeName\" value:\"volume-ff8ec137\" \u003e ","time":"2019-05-06T11:59:11Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerUnpublishVolume","GRPC.request":"volume_id:\"ff8ec137-7021-4504-a79f-bbc058e4b08d\" node_id:\"master\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T12:04:44Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T12:05:09Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T12:05:09Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T12:05:09Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T12:05:09Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T12:05:09Z"}
{"level":"info","msg":"DeleteVolume called","time":"2019-05-06T12:05:09Z","volume_id":"ff8ec137-7021-4504-a79f-bbc058e4b08d"}
{"GRPC.call":"/csi.v1.Controller/DeleteVolume","GRPC.request":"volume_id:\"ff8ec137-7021-4504-a79f-bbc058e4b08d\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T12:05:11Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T13:36:02Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T13:36:02Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T13:36:02Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T13:36:02Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T13:36:02Z"}
{"level":"info","msg":"CreateVolume called","time":"2019-05-06T13:36:02Z","volume_name":"pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"}
{"level":"info","msg":"Volume requested","planID":"d6570cfb-38fa-4467-92b3-e45d059bb249","sizeRequestGiB":10,"time":"2019-05-06T13:36:02Z","volume_name":"pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a"}
{"GRPC.call":"/csi.v1.Controller/CreateVolume","GRPC.request":"name:\"pvc-de8fa832-7003-11e9-8581-0cc47ab58a7a\" capacity_range:\u003crequired_bytes:1000000000 \u003e volume_capabilities:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:MULTI_NODE_MULTI_WRITER \u003e \u003e parameters:\u003ckey:\"plan\" value:\"performance\" \u003e ","level":"info","msg":"GRPC response: volume:\u003ccapacity_bytes:10737418240 volume_id:\"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c\" \u003e ","time":"2019-05-06T13:36:03Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerPublishVolume","GRPC.request":"volume_id:\"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c\" node_id:\"master\" volume_capability:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:MULTI_NODE_MULTI_WRITER \u003e \u003e volume_context:\u003ckey:\"storage.kubernetes.io/csiProvisionerIdentity\" value:\"1557143943332-8081-net.packet.csi\" \u003e ","level":"info","msg":"GRPC response: publish_context:\u003ckey:\"AttachmentId\" value:\"3b4c118f-4602-4b8f-b7d5-9fb42b81a503\" \u003e publish_context:\u003ckey:\"VolumeId\" value:\"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c\" \u003e publish_context:\u003ckey:\"VolumeName\" value:\"volume-22be26ad\" \u003e ","time":"2019-05-06T13:36:06Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T14:36:30Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T14:36:30Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T14:36:30Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T14:36:30Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T14:36:30Z"}
{"level":"info","msg":"CreateVolume called","time":"2019-05-06T14:36:30Z","volume_name":"pvc-56600899-700c-11e9-8581-0cc47ab58a7a"}
{"level":"info","msg":"Volume requested","planID":"87728148-3155-4992-a730-8d1e6aca8a32","sizeRequestGiB":10,"time":"2019-05-06T14:36:30Z","volume_name":"pvc-56600899-700c-11e9-8581-0cc47ab58a7a"}
{"GRPC.call":"/csi.v1.Controller/CreateVolume","GRPC.request":"name:\"pvc-56600899-700c-11e9-8581-0cc47ab58a7a\" capacity_range:\u003crequired_bytes:1073741824 \u003e volume_capabilities:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e parameters:\u003ckey:\"plan\" value:\"standard\" \u003e ","level":"info","msg":"GRPC response: volume:\u003ccapacity_bytes:10737418240 volume_id:\"5b8c530a-11fd-419c-a559-b27860d06a10\" \u003e ","time":"2019-05-06T14:36:31Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerPublishVolume","GRPC.request":"volume_id:\"5b8c530a-11fd-419c-a559-b27860d06a10\" node_id:\"master\" volume_capability:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e volume_context:\u003ckey:\"storage.kubernetes.io/csiProvisionerIdentity\" value:\"1557143943332-8081-net.packet.csi\" \u003e ","level":"info","msg":"GRPC response: publish_context:\u003ckey:\"AttachmentId\" value:\"9131360a-7109-4e9a-bead-14c4adb79da6\" \u003e publish_context:\u003ckey:\"VolumeId\" value:\"5b8c530a-11fd-419c-a559-b27860d06a10\" \u003e publish_context:\u003ckey:\"VolumeName\" value:\"volume-5b8c530a\" \u003e ","time":"2019-05-06T14:36:35Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerUnpublishVolume","GRPC.request":"volume_id:\"5b8c530a-11fd-419c-a559-b27860d06a10\" node_id:\"master\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T14:46:59Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T14:47:00Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T14:47:00Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T14:47:00Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T14:47:00Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T14:47:00Z"}
{"level":"info","msg":"DeleteVolume called","time":"2019-05-06T14:47:00Z","volume_id":"5b8c530a-11fd-419c-a559-b27860d06a10"}
{"GRPC.call":"/csi.v1.Controller/DeleteVolume","GRPC.request":"volume_id:\"5b8c530a-11fd-419c-a559-b27860d06a10\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T14:47:02Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerUnpublishVolume","GRPC.request":"volume_id:\"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c\" node_id:\"master\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T14:48:19Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T14:48:32Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T14:48:32Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T14:48:32Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T14:48:32Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T14:48:32Z"}
{"level":"info","msg":"DeleteVolume called","time":"2019-05-06T14:48:32Z","volume_id":"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c"}
{"GRPC.call":"/csi.v1.Controller/DeleteVolume","GRPC.request":"volume_id:\"22be26ad-6c16-4d8f-9d06-d8117b8a4c8c\" ","level":"info","msg":"GRPC response: ","time":"2019-05-06T14:48:34Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginCapabilities called","time":"2019-05-06T14:48:54Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003cservice:\u003ctype:CONTROLLER_SERVICE \u003e \u003e ","time":"2019-05-06T14:48:54Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerGetCapabilities","GRPC.request":"","level":"info","msg":"GRPC response: capabilities:\u003crpc:\u003ctype:CREATE_DELETE_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:PUBLISH_UNPUBLISH_VOLUME \u003e \u003e capabilities:\u003crpc:\u003ctype:LIST_VOLUMES \u003e \u003e ","time":"2019-05-06T14:48:54Z"}
{"level":"info","msg":"PacketIdentityServer.GetPluginInfo called","time":"2019-05-06T14:48:54Z"}
{"GRPC.call":"/csi.v1.Identity/GetPluginInfo","GRPC.request":"","level":"info","msg":"GRPC response: name:\"net.packet.csi\" vendor_version:\"UNKNOWN\" ","time":"2019-05-06T14:48:54Z"}
{"level":"info","msg":"CreateVolume called","time":"2019-05-06T14:48:54Z","volume_name":"pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"}
{"level":"info","msg":"Volume requested","planID":"87728148-3155-4992-a730-8d1e6aca8a32","sizeRequestGiB":10,"time":"2019-05-06T14:48:54Z","volume_name":"pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a"}
{"GRPC.call":"/csi.v1.Controller/CreateVolume","GRPC.request":"name:\"pvc-11e21ced-700e-11e9-8581-0cc47ab58a7a\" capacity_range:\u003crequired_bytes:1073741824 \u003e volume_capabilities:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e parameters:\u003ckey:\"plan\" value:\"standard\" \u003e ","level":"info","msg":"GRPC response: volume:\u003ccapacity_bytes:10737418240 volume_id:\"bfd30da9-4229-4b65-934a-1c79ebbb9267\" \u003e ","time":"2019-05-06T14:48:55Z"}
{"GRPC.call":"/csi.v1.Controller/ControllerPublishVolume","GRPC.request":"volume_id:\"bfd30da9-4229-4b65-934a-1c79ebbb9267\" node_id:\"master\" volume_capability:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e volume_context:\u003ckey:\"storage.kubernetes.io/csiProvisionerIdentity\" value:\"1557143943332-8081-net.packet.csi\" \u003e ","level":"info","msg":"GRPC response: publish_context:\u003ckey:\"AttachmentId\" value:\"d6b5a14a-6363-443f-b4b2-25d3003d9b4e\" \u003e publish_context:\u003ckey:\"VolumeId\" value:\"bfd30da9-4229-4b65-934a-1c79ebbb9267\" \u003e publish_context:\u003ckey:\"VolumeName\" value:\"volume-bfd30da9\" \u003e ","time":"2019-05-06T14:48:59Z"}
@jprukner
Copy link
Author

jprukner commented May 6, 2019 

root@master:/var/lib/kubelet/pods# kubectl version
Client Version: version.Info{Major:"1", Minor:"14", GitVersion:"v1.14.1", GitCommit:"b7394102d6ef778017f2ca4046abbaa23b88c290", GitTreeState:"clean", BuildDate:"2019-04-08T17:11:31Z", GoVersion:"go1.12.1", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"14", GitVersion:"v1.14.1", GitCommit:"b7394102d6ef778017f2ca4046abbaa23b88c290", GitTreeState:"clean", BuildDate:"2019-04-08T17:02:58Z", GoVersion:"go1.12.1", Compiler:"gc", Platform:"linux/amd64"}

@jprukner
Copy link
Author

jprukner commented May 6, 2019 

root@master:~/csi-packet/deploy/kubernetes# ps faux | grep allow-privileged
root      1551 11.0  1.3 2091040 107448 ?      Ssl  08:26  56:04 /usr/bin/kubelet --bootstrap-kubeconfig=/etc/kubernetes/bootstrap-kubelet.conf --kubeconfig=/etc/kubernetes/kubelet.conf --config=/var/lib/kubelet/config.yaml --cgroup-driver=cgroupfs --network-plugin=cni --pod-infra-container-image=k8s.gcr.io/pause:3.1 --resolv-conf=/run/systemd/resolve/resolv.conf --node-ip=10.100.127.1 --allow-privileged=true
root     18072  0.0  0.0  13108  1084 pts/0    S+   16:55   0:00          \_ grep --color=auto allow-privileged
root      2532  5.5  3.6 475232 300000 ?       Ssl  08:26  28:15      |   \_ kube-apiserver --advertise-address=10.100.127.1 --allow-privileged=true --authorization-mode=Node,RBAC --client-ca-file=/etc/kubernetes/pki/ca.crt --enable-admission-plugins=NodeRestriction --enable-bootstrap-token-auth=true --etcd-cafile=/etc/kubernetes/pki/etcd/ca.crt --etcd-certfile=/etc/kubernetes/pki/apiserver-etcd-client.crt --etcd-keyfile=/etc/kubernetes/pki/apiserver-etcd-client.key --etcd-servers=https://127.0.0.1:2379 --insecure-port=0 --kubelet-client-certificate=/etc/kubernetes/pki/apiserver-kubelet-client.crt --kubelet-client-key=/etc/kubernetes/pki/apiserver-kubelet-client.key --kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname --proxy-client-cert-file=/etc/kubernetes/pki/front-proxy-client.crt --proxy-client-key-file=/etc/kubernetes/pki/front-proxy-client.key --requestheader-allowed-names=front-proxy-client --requestheader-client-ca-file=/etc/kubernetes/pki/front-proxy-ca.crt --requestheader-extra-headers-prefix=X-Remote-Extra- --requestheader-group-headers=X-Remote-Group --requestheader-username-headers=X-Remote-User --secure-port=6443 --service-account-key-file=/etc/kubernetes/pki/sa.pub --service-cluster-ip-range=10.96.0.0/12 --tls-cert-file=/etc/kubernetes/pki/apiserver.crt --tls-private-key-file=/etc/kubernetes/pki/apiserver.key

@jprukner
Copy link
Author

jprukner commented May 6, 2019 •
edited
Loading

Tried to update csi images to tag v1.1.0, deleted volumes of orphaned pods, but still same issue.

@deitch
Copy link
Contributor

deitch commented May 7, 2019

Hey @jprukner we are going to take a look. Thank you for lots of debugging info; makes our lives easier. :-)

To be clear: you just ran kubectl apply -f demo-deployment.yaml after installing the relevant secret?

@jprukner
Copy link
Author

jprukner commented May 7, 2019 •
edited
Loading

Hey @deitch thanks for the fast response.

Actually, I was trying to get CrunchyData's postgres-operator running. An attachment of the volume to a database failed. I started debugging it and encountered an error in csi-packet-controller csi-attatcher:

I0507 13:42:09.002975       1 csi_handler.go:524] Can't get CSINodeInfo master: csinodeinfos.csi.storage.k8s.io "master" is forbidden: User "system:serviceaccount:kube-system:csi-controller-sa" cannot get resource "csinodeinfos" in API group "csi.storage.k8s.io" at the cluster scope

After I added the demanded privilege, the volume got attatched but I ran into the error with mounting described in this issue.
I tried to rerun kubectl apply -f demo-deployment.yaml a few times just to make sure it's not a bug in postgres-operator.
I just got fresh master up to make debugging easier, ran kubectl apply -f demo-deployment.yaml and added the privilege to clusterrole csi-external-attacher. The result is the same:

root@master:~# KUBE_EDITOR=nano kubectl -n kube-system edit clusterrole csi-external-attacher 
clusterrole.rbac.authorization.k8s.io/csi-external-attacher edited
root@master:~# kubectl describe pod nginx-5f47999bdc-5r4fk 
Name:               nginx-5f47999bdc-5r4fk
Namespace:          default
Priority:           0
PriorityClassName:  <none>
Node:               master/10.100.127.1
Start Time:         Tue, 07 May 2019 13:42:03 +0000
Labels:             pod-template-hash=5f47999bdc
                    run=nginx
Annotations:        <none>
Status:             Pending
IP:                 
Controlled By:      ReplicaSet/nginx-5f47999bdc
Containers:
  nginx:
    Container ID:   
    Image:          nginx
    Image ID:       
    Port:           <none>
    Host Port:      <none>
    State:          Waiting
      Reason:       ContainerCreating
    Ready:          False
    Restart Count:  0
    Environment:    <none>
    Mounts:
      /var/lib/www/html from mypvc (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-2ngqk (ro)
Conditions:
  Type              Status
  Initialized       True 
  Ready             False 
  ContainersReady   False 
  PodScheduled      True 
Volumes:
  mypvc:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  podpvc
    ReadOnly:   false
  default-token-2ngqk:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  default-token-2ngqk
    Optional:    false
QoS Class:       BestEffort
Node-Selectors:  <none>
Tolerations:     node.kubernetes.io/not-ready:NoExecute for 300s
                 node.kubernetes.io/unreachable:NoExecute for 300s
Events:
  Type     Reason                  Age                 From                     Message
  ----     ------                  ----                ----                     -------
  Warning  FailedScheduling        12m (x4 over 13m)   default-scheduler        pod has unbound immediate PersistentVolumeClaims
  Normal   Scheduled               12m                 default-scheduler        Successfully assigned default/nginx-5f47999bdc-5r4fk to master
  Warning  FailedAttachVolume      12m (x6 over 12m)   attachdetach-controller  AttachVolume.Attach failed for volume "pvc-db321943-70cd-11e9-bf07-0cc47ab58906" : node "master" has no NodeID annotation
  Normal   SuccessfulAttachVolume  12m                 attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-db321943-70cd-11e9-bf07-0cc47ab58906"
  Warning  FailedMount             97s (x5 over 10m)   kubelet, master          Unable to mount volumes for pod "nginx-5f47999bdc-5r4fk_default(db3946bb-70cd-11e9-bf07-0cc47ab58906)": timeout expired waiting for volumes to attach or mount for pod "default"/"nginx-5f47999bdc-5r4fk". list of unmounted volumes=[mypvc]. list of unattached volumes=[mypvc default-token-2ngqk]
  Warning  FailedMount             26s (x12 over 11m)  kubelet, master          MountVolume.MountDevice failed for volume "pvc-db321943-70cd-11e9-bf07-0cc47ab58906" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

@deitch
Copy link
Contributor

deitch commented May 7, 2019

It sounds like there are two things here. One is a permissions issue with the attacher, the other a problem with mounting. Is that correct? The first should be an easy enough fix, the second will require more work to figure out.

You said you had a fresh cluster up. Can I hop onto it? I can message you my ssh public key.

@jprukner
Copy link
Author

jprukner commented May 8, 2019

Yeah, it is correct.
Sure. I have sent an email to avi@atomicinc.com.

@jprukner
Copy link
Author

jprukner commented May 11, 2019 •
edited
Loading

This call hangs https://github.com/packethost/csi-packet/blob/379e828113c454ea89ce3e3a8bd245aac819da7e/pkg/driver/node.go#L72 and causes the rpc call to timeout. That call is just execution of a command iscsiadm --mode discovery --portal <ip-goes-here> --type sendtargets --discover
When trying to run packet-block-storage-attach -m queue from https://support.packet.com/kb/articles/elastic-block-storage I get:

[ ok ] Restarting open-iscsi (via systemctl): open-iscsi.service.
[ ok ] Restarting open-iscsi (via systemctl): open-iscsi.service.
portal: 10.144.34.134 iqn: iqn.2013-05.com.daterainc:tc:01:sn:e7368dc5750d51b2
iscsiadm: No records found

any ideas? @deitch

@jprukner
Copy link
Author

Apparently, attaching a volume that is not active can cause issues. equinixmetal-archive/packngo#146

@jprukner
Copy link
Author

Another update. There is an issue open-iscsi/open-iscsi#155 where iscsiadm also blocks.

@jprukner
Copy link
Author

jprukner commented May 18, 2019 •
edited
Loading

@deitch Updating iscsiadm to the latest version from the master branch of open-iscsi helped. iscsiadm no longer hangs.
Now, I get error with creating filesystem:

{"endpoint":"unix:///csi/csi.sock","fsType":"ext4","level":"info","method":"NodeStageVolume","msg":"multipath check for /dev/sdb: volume-158f5aa5 (36001405ba790d2746e3474091ce85091) dm-0 DATERA,IBLOCK\nsize=10G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw\n`-+- policy='round-robin 0' prio=1 status=active\n  |- 2:0:0:0 sdb 8:16 active ready running\n  `- 3:0:0:0 sdc 8:32 active ready running\n","node":"master","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-39a641b7-7939-11e9-b729-0cc47a205c92/globalmount","time":"2019-05-18T06:55:42Z","volume_id":"158f5aa5-b5b0-4a24-b978-cbc2205317fb","volume_name":"volume-158f5aa5"}
{"args":"-F /dev/mapper/volume-158f5aa5","command":"mkfs.ext4","error":"exit status 1","level":"error","msg":"Error","out":"mke2fs 1.42.13 (17-May-2015)\nInvalid filesystem option set: has_journal,extent,huge_file,flex_bg,metadata_csum,64bit,dir_nlink,extra_isize\n","time":"2019-05-18T06:55:42Z"}
{"endpoint":"unix:///csi/csi.sock","fsType":"ext4","level":"info","method":"NodeStageVolume","msg":"formatMappedDevice error, exit status 1","node":"master","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-39a641b7-7939-11e9-b729-0cc47a205c92/globalmount","time":"2019-05-18T06:55:42Z","volume_id":"158f5aa5-b5b0-4a24-b978-cbc2205317fb","volume_name":"volume-158f5aa5"}
{"GRPC.call":"/csi.v1.Node/NodeStageVolume","GRPC.request":"volume_id:\"158f5aa5-b5b0-4a24-b978-cbc2205317fb\" publish_context:\u003ckey:\"AttachmentId\" value:\"8a6b1e15-fb38-45a3-a79e-0e1ee703bb12\" \u003e publish_context:\u003ckey:\"VolumeId\" value:\"158f5aa5-b5b0-4a24-b978-cbc2205317fb\" \u003e publish_context:\u003ckey:\"VolumeName\" value:\"volume-158f5aa5\" \u003e staging_target_path:\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-39a641b7-7939-11e9-b729-0cc47a205c92/globalmount\" volume_capability:\u003cmount:\u003cfs_type:\"ext4\" \u003e access_mode:\u003cmode:SINGLE_NODE_WRITER \u003e \u003e volume_context:\u003ckey:\"storage.kubernetes.io/csiProvisionerIdentity\" value:\"1558162212367-8081-net.packet.csi\" \u003e ","level":"error","msg":"GRPC error: rpc error: code = Unknown desc = formatMappedDevice error, exit status 1","time":"2019-05-18T06:55:42Z"}

@jprukner
Copy link
Author

jprukner commented May 18, 2019 •
edited
Loading

I updated base of docker image to ubuntu:latest to get newer mkfs.ext4
Now getting an error already mounted:

{"endpoint":"unix:///csi/csi.sock","fsType":"ext4","level":"info","method":"NodeStageVolume","msg":"mounting mapped device","node":"master","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-0f89dd39-793e-11e9-b729-0cc47a205c92/globalmount","time":"2019-05-18T07:27:21Z","volume_id":"82bd3b49-f0e3-4b4b-917d-13f3fbd96f10","volume_name":"volume-82bd3b49"}
{"args":"-t ext4 --source /dev/mapper/volume-82bd3b49 --target /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-0f89dd39-793e-11e9-b729-0cc47a205c92/globalmount","command":"mount","error":"exit status 32","level":"error","msg":"Error","out":"mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-0f89dd39-793e-11e9-b729-0cc47a205c92/globalmount: /dev/mapper/volume-82bd3b49 already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-0f89dd39-793e-11e9-b729-0cc47a205c92/globalmount.\n","time":"2019-05-18T07:27:21Z"}

Giving up on this issue. I will use rook until this project gets a bit more matured.

@deitch deitch reopened this Sep 5, 2019
This was referenced Sep 11, 2019
Closed
Closed
@deitch
Copy link
Contributor

deitch commented Sep 18, 2019

@jprukner thanks for your help in reporting these. The open-iscsi off of latest, up-to-date mkfs.ext4 via more recent base image, permissions, etc. have all been resolved and merged into the most recent releases. That leaves just the most recent issue reported here. We are working on it.

Right now, it is plain vanilla k8s with the demo-deployment.yaml. If there is a different scenario, please let us know.

@deitch
Copy link
Contributor

deitch commented Oct 1, 2019

At this point, with all of the issues addressed, we are going to close the issue. If it recurs, we can reopen.

@deitch deitch closed this as completed Oct 1, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@deitch @jprukner