openebs / zfs-localpv Goto Github PK

    I0409 17:26:53.814862 1 operation_generator.go:359] AttachVolume.Attach succeeded for volume "pvc-f029b12f-92d6-44fa-aa28-33a64f420b34" (UniqueName: "kubernetes.io/csi/zfs.csi.openebs.io^pvc-f029b12f-92d6-44fa-aa28-33a64f420b34") from node "halfling-mexico"```

Volumes provisioned by the zfs provider all seem to take >1hr to complete the mounting of a volume. We haven't seen any throttling logs form the controller manager.

Happy to provide any additional information.

namespace/openebs created
customresourcedefinition.apiextensions.k8s.io/zfsvolumes.zfs.openebs.io created
customresourcedefinition.apiextensions.k8s.io/zfssnapshots.zfs.openebs.io created
error: error validating "https://raw.githubusercontent.com/openebs/zfs-localpv/master/deploy/zfs-operator.yaml": error validating data: ValidationError(CSIDriver.spec): unknown field "volumeLifecycleModes" in io.k8s.api.storage.v1beta1.CSIDriverSpec; if you choose to ignore these errors, turn validation off with --validate=false

Filesystem                                          Size  Used Avail Use% Mounted on
overlay                                              98G  9.3G   84G  10% /
tmpfs                                                64M     0   64M   0% /dev
tmpfs                                               3.9G     0  3.9G   0% /sys/fs/cgroup
/dev/sda1                                            98G  9.3G   84G  10% /etc/hosts
shm                                                  64M     0   64M   0% /dev/shm
test-pool/pvc-6c79f1f9-dc91-408e-b0e1-aa9120dae6b3  2.0G  215M  1.8G  11% /var/lib/mysql
tmpfs                                               3.9G   12K  3.9G   1% /run/secrets/kubernetes.io/serviceaccount
tmpfs                                               3.9G     0  3.9G   0% /proc/acpi
tmpfs                                               3.9G     0  3.9G   0% /proc/scsi
tmpfs                                               3.9G     0  3.9G   0% /sys/firmware

root@percona1-7c776f8558-6cskw:/# df -h
Filesystem                                          Size  Used Avail Use% Mounted on
overlay                                              98G  9.3G   84G  10% /
tmpfs                                                64M     0   64M   0% /dev
tmpfs                                               3.9G     0  3.9G   0% /sys/fs/cgroup
/dev/sda1                                            98G  9.3G   84G  10% /etc/hosts
shm                                                  64M     0   64M   0% /dev/shm
test-pool/pvc-fe8c7583-9896-4ae8-9e59-0393f0858279  9.7G  215M  9.4G   3% /var/lib/mysql
tmpfs                                               3.9G   12K  3.9G   1% /run/secrets/kubernetes.io/serviceaccount
tmpfs                                               3.9G     0  3.9G   0% /proc/acpi
tmpfs                                               3.9G     0  3.9G   0% /proc/scsi
tmpfs                                               3.9G     0  3.9G   0% /sys/firmware

Events:
  Type     Reason       Age                    From                             Message
  ----     ------       ----                   ----                             -------
  Normal   Scheduled    6m48s                  default-scheduler                Successfully assigned default/app-busybox-84869957c7-j4hpc to d2iq-node1.mayalabs.io
  Warning  FailedMount  4m45s                  kubelet, d2iq-node1.mayalabs.io  Unable to mount volumes for pod "app-busybox-84869957c7-j4hpc_default(be9b5315-edd9-40fd-bb64-eeb0f1a18740)": timeout expired waiting for volumes to attach or mount for pod "default"/"app-busybox-84869957c7-j4hpc". list of unmounted volumes=[data-vol]. list of unattached volumes=[data-vol default-token-nf4rn]
  Warning  FailedMount  4m37s (x9 over 6m48s)  kubelet, d2iq-node1.mayalabs.io  MountVolume.SetUp failed for volume "pvc-b8914c43-2a53-49aa-b43f-f6211f029aba" : rpc error: code = Internal desc = rpc error: code = Internal desc = not able to format and mount the zvol

I0703 11:40:21.581453       1 mount_linux.go:454] `fsck` error fsck from util-linux 2.34
fsck.ext2: Bad magic number in super-block while trying to open /dev/zd0
/dev/zd0: 
The superblock could not be read or does not describe a valid ext2/ext3/ext4
filesystem.  If the device is valid and it really contains an ext2/ext3/ext4
filesystem (and not swap or ufs or something else), then the superblock
is corrupt, and you might try running e2fsck with an alternate superblock:
    e2fsck -b 8193 <device>
 or
    e2fsck -b 32768 <device>

E0703 11:42:32.350511       1 mount.go:21] zfspv: failed to mount volume /dev/zvol/test/pvc-b8914c43-2a53-49aa-b43f-f6211f029aba [xfs] to /var/lib/kubelet/pods/be9b5315-edd9-40fd-bb64-eeb0f1a18740/volumes/kubernetes.io~csi/pvc-b8914c43-2a53-49aa-b43f-f6211f029aba/mount, error mount failed: exit status 32
Mounting command: mount
Mounting arguments: -t xfs -o defaults /dev/zvol/test/pvc-b8914c43-2a53-49aa-b43f-f6211f029aba /var/lib/kubelet/pods/be9b5315-edd9-40fd-bb64-eeb0f1a18740/volumes/kubernetes.io~csi/pvc-b8914c43-2a53-49aa-b43f-f6211f029aba/mount
Output: mount: /var/lib/kubelet/pods/be9b5315-edd9-40fd-bb64-eeb0f1a18740/volumes/kubernetes.io~csi/pvc-b8914c43-2a53-49aa-b43f-f6211f029aba/mount: wrong fs type, bad option, bad superblock on /dev/zd0, missing codepage or helper program, or other error.

[root@d2iq-master ~]# cat /etc/os-release 
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"

Warning  FailedMount  20m (x5 over 20m)    kubelet, localhost.localdomain  MountVolume.SetUp failed for volume "libzpool" : hostPath type check failed: /lib/libzpool.so.2.0.0 is not a file
  Warning  FailedMount  20m (x5 over 20m)    kubelet, localhost.localdomain  MountVolume.SetUp failed for volume "libnvpair" : hostPath type check failed: /lib/libnvpair.so.1.0.1 is not a file

time="2020-06-19T11:30:28Z" level=info msg="GRPC call: /csi.v1.Node/NodeGetCapabilities"
time="2020-06-19T11:30:28Z" level=info msg="GRPC request: {}"
time="2020-06-19T11:30:28Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}}]}"
time="2020-06-19T11:30:28Z" level=info msg="GRPC call: /csi.v1.Node/NodeGetVolumeStats"
time="2020-06-19T11:30:28Z" level=info msg="GRPC request: {\"volume_id\":\"pvc-794118b5-143b-49a1-99e8-4c2b80a74776\",\"volume_path\":\"/var/lib/kubelet/pods/3afb1e57-47db-4f22-948c-273fe5c53633/volumes/kubernetes.io~csi/pvc-794118b5-143b-49a1-99e8-4c2b80a74776/mount\"}"
time="2020-06-19T11:30:28Z" level=info msg="GRPC response: {\"usage\":[{\"available\":4294836224,\"total\":4294967296,\"unit\":1,\"used\":131072},{\"available\":8388560,\"total\":8388566,\"unit\":2,\"used\":6}]}"

time="2020-07-15T09:10:51Z" level=error msg="zfspv: failed to mount volume /dev/zvol/zfs-test-pool/pvc-05e22f2a-9901-40ba-817d-82a43a922713 [xfs] to /var/lib/kubelet/pods/341b2fca-8430-45d1-9009-375a81588210/volumes/kubernetes.io~csi/pvc-05e22f2a-9901-40ba-817d-82a43a922713/mount, error mount failed: exit status 32\nMounting command: mount\nMounting arguments: -t xfs -o defaults /dev/zvol/zfs-test-pool/pvc-05e22f2a-9901-40ba-817d-82a43a922713 /var/lib/kubelet/pods/341b2fca-8430-45d1-9009-375a81588210/volumes/kubernetes.io~csi/pvc-05e22f2a-9901-40ba-817d-82a43a922713/mount\nOutput: mount: /var/lib/kubelet/pods/341b2fca-8430-45d1-9009-375a81588210/volumes/kubernetes.io~csi/pvc-05e22f2a-9901-40ba-817d-82a43a922713/mount: wrong fs type, bad option, bad superblock on /dev/zd16, missing codepage or helper program, or other error.\n\n"

[ 6421.004650] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6421.603229] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6422.705286] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6424.812780] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6428.937560] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6437.072385] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6453.143135] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount
[ 6485.287202] XFS (zd16): Filesystem has duplicate UUID 3af6518b-8f14-4585-b513-949053e63a4c - can't mount

│ csi-node-driver-registrar I0429 16:06:11.322451       1 main.go:110] Version: v1.2.0-0-g6ef000ae                                                                                                         │
│ csi-node-driver-registrar I0429 16:06:11.322531       1 main.go:120] Attempting to open a gRPC connection with: "/plugin/csi.sock"                                                                       │
│ csi-node-driver-registrar I0429 16:06:11.322545       1 connection.go:151] Connecting to unix:///plugin/csi.sock                                                                                         │
│ csi-node-driver-registrar I0429 16:06:11.322870       1 main.go:127] Calling CSI driver to discover driver name                                                                                          │
│ csi-node-driver-registrar I0429 16:06:11.323255       1 connection.go:180] GRPC call: /csi.v1.Identity/GetPluginInfo                                                                                     │
│ csi-node-driver-registrar I0429 16:06:11.323287       1 connection.go:181] GRPC request: {}                                                                                                              │
│ csi-node-driver-registrar I0429 16:06:11.326587       1 connection.go:183] GRPC response: {"name":"zfs.csi.openebs.io","vendor_version":"master-02bc587:04-28-2020"}                                     │
│ csi-node-driver-registrar I0429 16:06:11.327524       1 connection.go:184] GRPC error: <nil>                                                                                                             │
│ csi-node-driver-registrar I0429 16:06:11.327544       1 main.go:137] CSI driver name: "zfs.csi.openebs.io"                                                                                               │
│ csi-node-driver-registrar I0429 16:06:11.327615       1 node_register.go:58] Starting Registration Server at: /registration/zfs.csi.openebs.io-reg.sock                                                  │
│ csi-node-driver-registrar I0429 16:06:11.327798       1 node_register.go:67] Registration Server started at: /registration/zfs.csi.openebs.io-reg.sock                                                   │
│ csi-node-driver-registrar I0429 16:06:11.471563       1 main.go:77] Received GetInfo call: &InfoRequest{}                                                                                                │
│ csi-node-driver-registrar I0429 16:06:12.471906       1 main.go:77] Received GetInfo call: &InfoRequest{}                                                                                                │
│ csi-node-driver-registrar I0429 16:06:12.821947       1 main.go:87] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:false,Error:RegisterPlugin error -- plugin registration │
│  failed with err: error updating Node object with CSI driver node info: error updating node: timed out waiting for the condition; caused by: detected topology value collision: driver reported "kuberne │
│ tes.io/hostname":"ip-10-99-90-189.ap-south-1.compute.internal" but existing label is "kubernetes.io/hostname":"ip-10-99-90-189",}                                                                        │
│ csi-node-driver-registrar E0429 16:06:12.822033       1 main.go:89] Registration process failed with error: RegisterPlugin error -- plugin registration failed with err: error updating Node object with │
│  CSI driver node info: error updating node: timed out waiting for the condition; caused by: detected topology value collision: driver reported "kubernetes.io/hostname":"ip-10-99-90-189.ap-south-1.comp │
│ ute.internal" but existing label is "kubernetes.io/hostname":"ip-10-99-90-189", restarting registration container.                                                                                       │
│ csi-node-driver-registrar stream closed

  Type     Reason                  Age                   From                     Message
  Warning  FailedScheduling        <unknown>             default-scheduler        Failed to bind volumes: pv "pvc-aeadf930-2f7f-4e66-94d3-bd4366e0550b" node affinity doesn't match node "e2e1-node3": No matching NodeSelectorTerms
  Normal   Scheduled               <unknown>             default-scheduler        Successfully assigned aman/percona1-7c776f8558-l2vxk to e2e1-node1
  Warning  FailedScheduling        <unknown>             default-scheduler        AssumePod failed: pod 300233c3-1de6-42a4-87d2-82bba6c284a3 is in the cache, so can't be assumed
  Normal   SuccessfulAttachVolume  5m17s                 attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-aeadf930-2f7f-4e66-94d3-bd4366e0550b"
  Warning  FailedMount             3m14s                 kubelet, e2e1-node1      Unable to attach or mount volumes: unmounted volumes=[data-vol], unattached volumes=[data-vol default-token-tjqfq]: timed out waiting for the condition
  Warning  FailedMount             62s (x10 over 5m13s)  kubelet, e2e1-node1      MountVolume.SetUp failed for volume "pvc-aeadf930-2f7f-4e66-94d3-bd4366e0550b" : kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = Internal desc = rpc error: code = Internal desc = not able to format and mount the zvol
  Warning  FailedMount             58s                   kubelet, e2e1-node1      Unable to attach or mount volumes: unmounted volumes=[data-vol], unattached volumes=[default-token-tjqfq data-vol]: timed out waiting for the condition

kind: StorageClass
metadata:
  name: zfs-sc
allowVolumeExpansion: true
parameters:
  volblocksize: "4k"
  compression: "off"
  dedup: "off"
  fstype: "xfs"
  poolname: "test-pool"
provisioner: zfs.csi.openebs.io
volumeBindingMode: WaitForFirstConsumer

kind: StorageClass
metadata:
  name: openebs-zfspv1
allowVolumeExpansion: true
parameters:
  fstype: "xfs"
  poolname: "zfspv-pool"
provisioner: zfs.csi.openebs.io
volumeBindingMode: WaitForFirstConsumer
mountOptions:
  - nouuid

local/pv/pvc-086ec32f-cce0-4009-8948-1ab6d4ccb839                                             7.59G   592G     7.59G  /var/lib/kubelet/pods/c6fa7984-2760-47f7-a105-3f2aa079db3e/volumes/kubernetes.io~csi/pvc-086ec32f-cce0-4009-8948-1ab6d4ccb839/mount
local/pv/pvc-370d7921-6a33-4336-ab85-2ddd789c576f                                             4.84M  10.0G     4.84M  /var/lib/kubelet/pods/64222e8a-8690-450b-8bc5-58868d8aa6bd/volumes/kubernetes.io~csi/pvc-370d7921-6a33-4336-ab85-2ddd789c576f/mount
local/pv/pvc-e1275578-6abd-4401-8402-9eb1298cfdb7                                             11.4G  88.6G     11.4G  /var/lib/kubelet/pods/e70a4494-14e7-481a-8d0c-424d20d1d876/volumes/kubernetes.io~csi/pvc-e1275578-6abd-4401-8402-9eb1298cfdb7/mount
local/pv/pvc-e3f70edf-9479-4e0b-bc21-0b00ee426307                                              204K  1024M      204K  /var/lib/kubelet/pods/7cf7f87d-fc90-4c21-a1c8-e7a605cf16bf/volumes/kubernetes.io~csi/pvc-e3f70edf-9479-4e0b-bc21-0b00ee426307/mount

❯ kubectl get zfsvolumes.zfs.openebs.io -A | rg textile
openebs     pvc-04230116-1719-4fc9-87e9-6bcbbb1440ac   local/pv   halfling-textile   8589934592                                 zfs                         112d
openebs     pvc-086ec32f-cce0-4009-8948-1ab6d4ccb839   local/pv   halfling-textile   644245094400                               zfs                         11d
openebs     pvc-370d7921-6a33-4336-ab85-2ddd789c576f   local/pv   halfling-textile   10737418240                                zfs                         43d
openebs     pvc-66cb5b8b-f446-414d-b451-8ddc66a1cdfe   local/pv   halfling-textile   8589934592                                 zfs                         112d
openebs     pvc-e1275578-6abd-4401-8402-9eb1298cfdb7   local/pv   halfling-textile   107374182400                               zfs                         43d
openebs     pvc-e3f70edf-9479-4e0b-bc21-0b00ee426307   local/pv   halfling-textile   1073741824                                 zfs                         29d

devuser@rack2:~$ kubectl get pvc --all-namespaces
No resources found.
devuser@rack2:~$ kubectl get zv -n openebs
NAME                                       ZPOOL   NODE        SIZE         STATUS    FILESYSTEM   AGE
pvc-c35668aa-5415-4efc-9d4f-403d262947b8   aman    k8s-node1   4294967296   Pending   zfs          12m

could not create volume rpool/k3s/openebs/pvc-9c375c67-4858-481e-ace4-83820f7221df cmd [create -o quota=4294967296 -o recordsize=4k -o dedup=off -o compression=on -o mountpoint=none rpool/k3s/openebs/pvc-9c375c67-4858-481e-ace4-83820f7221df] error: zfs: /lib/x86_64-linux-gnu/libc.so.6: version `GLIBC_2.28' not found (required by /lib/libzfs.so.2)\n"
E0321 13:03:40.406946       1 volume.go:252] error syncing

Nov  4 08:41:01 kuber1 containerd[1168]: time="2019-11-04T08:41:01.360357115Z" level=info msg="shim containerd-shim started" address="/containerd-shim/moby/28b3094c2c5b29608258e41e50438880c06aec988e4457779014c1becd2c6bf4/shim.sock" debug=false pid=6083
Nov  4 08:41:02 kuber1 kubelet[1130]: I1104 08:41:02.186118    1130 operation_generator.go:193] parsed scheme: ""
Nov  4 08:41:02 kuber1 kubelet[1130]: I1104 08:41:02.186191    1130 operation_generator.go:193] scheme "" not registered, fallback to default scheme
Nov  4 08:41:02 kuber1 kubelet[1130]: I1104 08:41:02.186227    1130 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/zfs-localpv/csi.sock 0  <nil>}] <nil>}
Nov  4 08:41:02 kuber1 kubelet[1130]: I1104 08:41:02.186283    1130 clientconn.go:577] ClientConn switching balancer to "pick_first"
Nov  4 08:41:02 kuber1 kubelet[1130]: E1104 08:41:02.190140    1130 goroutinemap.go:150] Operation for "/var/lib/kubelet/plugins/zfs-localpv/csi.sock" failed. No retries permitted until 2019-11-04 08:41:02.69010915 +0000 UTC m=+419.701334758 (durationBeforeRetry 500ms). Error: "RegisterPlugin error -- failed to get plugin info using RPC GetInfo at socket /var/lib/kubelet/plugins/zfs-localpv/csi.sock, err: rpc error: code = Unimplemented desc = unknown service pluginregistration.Registration"
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.186524    1130 operation_generator.go:193] parsed scheme: ""
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.187000    1130 operation_generator.go:193] scheme "" not registered, fallback to default scheme
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.187715    1130 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins_registry/zfs-localpv-reg.sock 0  <nil>}] <nil>}
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.186612    1130 operation_generator.go:193] parsed scheme: ""
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.187941    1130 clientconn.go:577] ClientConn switching balancer to "pick_first"
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.188155    1130 operation_generator.go:193] scheme "" not registered, fallback to default scheme
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.188476    1130 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/zfs-localpv/csi.sock 0  <nil>}] <nil>}
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.188612    1130 clientconn.go:577] ClientConn switching balancer to "pick_first"
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.189827    1130 csi_plugin.go:101] kubernetes.io/csi: Trying to validate a new CSI Driver with name: zfs-localpv endpoint: /var/lib/kubelet/plugins/zfs-localpv/csi.sock versions: 1.0.0, foundInDeprecatedDir: false
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.189889    1130 csi_plugin.go:120] kubernetes.io/csi: Register new plugin with name: zfs-localpv at endpoint: /var/lib/kubelet/plugins/zfs-localpv/csi.sock
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.190503    1130 clientconn.go:104] parsed scheme: ""
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.190555    1130 clientconn.go:104] scheme "" not registered, fallback to default scheme
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.190582    1130 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/zfs-localpv/csi.sock 0  <nil>}] <nil>}
Nov  4 08:41:03 kuber1 kubelet[1130]: I1104 08:41:03.190597    1130 clientconn.go:577] ClientConn switching balancer to "pick_first"
Nov  4 08:41:03 kuber1 kubelet[1130]: E1104 08:41:03.192114    1130 goroutinemap.go:150] Operation for "/var/lib/kubelet/plugins/zfs-localpv/csi.sock" failed. No retries permitted until 2019-11-04 08:41:04.192082873 +0000 UTC m=+421.203308506 (durationBeforeRetry 1s). Error: "RegisterPlugin error -- failed to get plugin info using RPC GetInfo at socket /var/lib/kubelet/plugins/zfs-localpv/csi.sock, err: rpc error: code = Unimplemented desc = unknown service pluginregistration.Registration"