Volume mount with Kubernetes fails

[mausquirk]

this is a request for help:

Orchestrator and version (e.g. Kubernetes, DC/OS, Swarm)
Kubernetes 1.7

Kubernetes master is running at https://bla.northeurope.cloudapp.azure.com
Heapster is running at https://bla.northeurope.cloudapp.azure.com/api/v1/namespaces/kube-system/services/heapster/proxy
KubeDNS is running at https://bla.northeurope.cloudapp.azure.com/api/v1/namespaces/kube-system/services/kube-dns/proxy
kubernetes-dashboard is running at https://bla.northeurope.cloudapp.azure.com/api/v1/namespaces/kube-system/services/kubernetes-dashboard/proxy
tiller-deploy is running at https://bla.northeurope.cloudapp.azure.com/api/v1/namespaces/kube-system/services/tiller-deploy/proxy

kubectl version 
Client Version: version.Info{Major:"1", Minor:"8", GitVersion:"v1.8.2", GitCommit:"bdaeafa71f6c7c04636251031f93464384d54963", GitTreeState:"clean", BuildDate:"2017-10-24T19:48:57Z", GoVersion:"go1.8.3", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"7", GitVersion:"v1.7.7", GitCommit:"8e1552342355496b62754e61ad5f802a0f3f1fa7", GitTreeState:"clean", BuildDate:"2017-09-28T23:56:03Z", GoVersion:"go1.8.3", Compiler:"gc", Platform:"linux/amd64"}

What happened:
Creating a MySQL Pod fails:
Kubernetes reports:

 Unable to mount volumes for pod "acousticity-generic-mysql-deployment-1784629133-s6sk4_acousticity(5dc15648-7015-11e8-ac80-000d3ab45bd1)": timeout expired waiting for volumes to attach/mount for pod "acousticity"/"acousticity-generic-mysql-deployment-1784629133-s6sk4". list of unattached/unmounted volumes=[acousticity-generic-mysql-pstorage]
Error syncing pod 

The container's log:

[Entrypoint] MySQL Docker Image 5.7.21-1.1.3
[Entrypoint] Initializing database
2018-06-14T20:59:11.481713Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-06-14T20:59:11.484034Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
2018-06-14T20:59:11.484087Z 0 [ERROR] Aborting 

Configuration:

 kubectl --namespace=acousticity describe persistentvolumeclaim acousticity-generic-mysql-pv-claim 
Name:          acousticity-generic-mysql-pv-claim
Namespace:     acousticity
StorageClass:  slow
Status:        Bound
Volume:        pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1
Labels:        <none>
Annotations:   pv.kubernetes.io/bind-completed=yes
               pv.kubernetes.io/bound-by-controller=yes
               volume.beta.kubernetes.io/storage-class=slow
               volume.beta.kubernetes.io/storage-provisioner=kubernetes.io/azure-disk
Capacity:      1Gi
Access Modes:  RWO
Events:
  Type    Reason                 Age   From                         Message
  ----    ------                 ----  ----                         -------
  Normal  ProvisioningSucceeded  51s   persistentvolume-controller  Successfully provisioned volume pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1 using kubernetes.io/azure-disk

Configruation

apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  labels:
    app: keyrock
    project: acousticity-generic
  name: acousticity-generic-mysql-deployment
spec:
  replicas: 1
  template:
    metadata:
      labels:
        app: mysql
        project: acousticity-generic
    spec:
      containers:
      - name: mysql
        image: mysql/mysql-server:5.7.21
        env: 
        - name: MYSQL_ROOT_PASSWORD
          value: "bla"  
        - name: MYSQL_ROOT_HOST
          value: "blaaa"
        ports:
        - containerPort: 3306
          protocol: TCP
        volumeMounts:
        - mountPath: /var/lib/mysql
          name: acousticity-generic-mysql-pstorage
      imagePullSecrets: 
      - name: registrykey
      restartPolicy: Always
      volumes:
      - name: acousticity-generic-mysql-pstorage
        persistentVolumeClaim:
          claimName: acousticity-generic-mysql-pv-claim

apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: acousticity-generic-mysql-pv-claim
  annotations: 
    volume.beta.kubernetes.io/storage-class: slow
spec:
  storageClassName: slow
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 1Gi

What you expected to happen:
I would expect it to work -> Pod running MySQL-Deamon starts successfully

How to reproduce it (as minimally and precisely as possible):
Run the configuration.

Anything else we need to know:
Claim get's bound with Persistent Volume. Azure Storage Explorer also shows according PageBlob.

[andyzhangx]

@mausquirk could you get the kubelet log from that agent node? need to ssh to that agent node and follow by:

id=`docker ps -a | grep "hyperkube kubele" | awk -F ' ' '{print $1}'`
docker logs $id > $id.log 2>&1
vi $id.log

[mausquirk]

error-log-failed-mount.log

[andyzhangx]

@mausquirk could you also run kubectl describe po POD-NAME, the logs you provided does not contain following text:

Unable to mount volumes for pod "acousticity-generic-mysql-deployment-1784629133-s6sk4_acousticity(5dc15648-7015-11e8-ac80-000d3ab45bd1)": timeout expired waiting for volumes to attach/mount for pod "acousticity"/"acousticity-generic-mysql-deployment-1784629133-s6sk4". list of unattached/unmounted volumes=[acousticity-generic-mysql-pstorage]

And what's your agent vm size? Could you help check whether that disk is already attached to the agent VM in azure portal? Thanks.

[mausquirk]

$ kubectl --namespace=acousticity describe pod acousticity-generic-mysql-deployment-1784629133-qb8zm 
Name:           acousticity-generic-mysql-deployment-1784629133-qb8zm
Namespace:      acousticity
Node:           k8s-agent-b4852c58-1/10.240.0.5
Start Time:     Fri, 15 Jun 2018 08:45:27 +0200
Labels:         app=mysql
                pod-template-hash=1784629133
                project=acousticity-generic
Annotations:    kubernetes.io/created-by={"kind":"SerializedReference","apiVersion":"v1","reference":{"kind":"ReplicaSet","namespace":"acousticity","name":"acousticity-generic-mysql-deployment-1784629133","uid":"9e1d...
Status:         Running
IP:             10.244.2.186
Created By:     ReplicaSet/acousticity-generic-mysql-deployment-1784629133
Controlled By:  ReplicaSet/acousticity-generic-mysql-deployment-1784629133
Containers:
  mysql:
    Container ID:   docker://829eb6432174600ffcbeec10f55f48732e3a9f355aaaa514e2ffc9ce2ba7cd31
    Image:          mysql/mysql-server:5.7.21
    Image ID:       docker-pullable://mysql/mysql-server@sha256:125a402f5b995d53a24d981c1111c8df624d4b49c51af6cf1fc2959dc449c8a7
    Port:           3306/TCP
    State:          Waiting
      Reason:       CrashLoopBackOff
    Last State:     Terminated
      Reason:       Error
      Exit Code:    1
      Started:      Fri, 15 Jun 2018 09:30:59 +0200
      Finished:     Fri, 15 Jun 2018 09:30:59 +0200
    Ready:          False
    Restart Count:  13
    Environment:
      MYSQL_ROOT_PASSWORD:  bla
      MYSQL_ROOT_HOST:      %
    Mounts:
      /var/lib/mysql from acousticity-generic-keyrock-mysql-pstorage (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-mxprk (ro)
Conditions:
  Type           Status
  Initialized    True 
  Ready          False 
  PodScheduled   True 
Volumes:
  acousticity-generic-keyrock-mysql-pstorage:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  acousticity-generic-mysql-pv-claim
    ReadOnly:   false
  default-token-mxprk:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  default-token-mxprk
    Optional:    false
QoS Class:       BestEffort
Node-Selectors:  <none>
Tolerations:     <none>
Events:
  Type     Reason                 Age                 From                           Message
  ----     ------                 ----                ----                           -------
  Normal   Scheduled              50m                 default-scheduler              Successfully assigned acousticity-generic-mysql-deployment-1784629133-qb8zm to k8s-agent-b4852c58-1
  Normal   SuccessfulMountVolume  50m                 kubelet, k8s-agent-b4852c58-1  MountVolume.SetUp succeeded for volume "default-token-mxprk"
  Warning  FailedMount            48m                 kubelet, k8s-agent-b4852c58-1  Unable to mount volumes for pod "acousticity-generic-mysql-deployment-1784629133-qb8zm_acousticity(b05fcde8-7067-11e8-ac80-000d3ab45bd1)": timeout expired waiting for volumes to attach/mount for pod "acousticity"/"acousticity-generic-mysql-deployment-1784629133-qb8zm". list of unattached/unmounted volumes=[acousticity-generic-keyrock-mysql-pstorage]
  Normal   SuccessfulMountVolume  46m                 kubelet, k8s-agent-b4852c58-1  MountVolume.SetUp succeeded for volume "pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1"
  Normal   Pulled                 4m (x14 over 46m)   kubelet, k8s-agent-b4852c58-1  Container image "mysql/mysql-server:5.7.21" already present on machine
  Normal   Created                4m (x14 over 46m)   kubelet, k8s-agent-b4852c58-1  Created container
  Normal   Started                4m (x14 over 46m)   kubelet, k8s-agent-b4852c58-1  Started container
  Warning  FailedSync             4s (x213 over 48m)  kubelet, k8s-agent-b4852c58-1  Error syncing pod
  Warning  BackOff                4s (x212 over 46m)  kubelet, k8s-agent-b4852c58-1  Back-off restarting failed container

$ kubectl --namespace=acousticity describe persistentvolumeclaim acousticity-generic-mysql-pv-claim 
Name:          acousticity-generic-mysql-pv-claim
Namespace:     acousticity
StorageClass:  slow
Status:        Bound
Volume:        pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1
Labels:        <none>
Annotations:   pv.kubernetes.io/bind-completed=yes
               pv.kubernetes.io/bound-by-controller=yes
               volume.beta.kubernetes.io/storage-class=slow
               volume.beta.kubernetes.io/storage-provisioner=kubernetes.io/azure-disk
Capacity:      1Gi
Access Modes:  RWO
Events:        <none>
kubectl --namespace=acousticity describe persistentvolume pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1
Name:            pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1
Labels:          <none>
Annotations:     pv.kubernetes.io/bound-by-controller=yes
                 pv.kubernetes.io/provisioned-by=kubernetes.io/azure-disk
                 volumehelper.VolumeDynamicallyCreatedByKey=azure-disk-dynamic-provisioner
StorageClass:    slow
Status:          Bound
Claim:           acousticity/acousticity-generic-mysql-pv-claim
Reclaim Policy:  Delete
Access Modes:    RWO
Capacity:        1Gi
Message:         
Source:
    Type:         AzureDisk (an Azure Data Disk mount on the host and bind mount to the pod)
    DiskName:     innetagmgmt-dynamic-pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1
    DiskURI:      https://pvc3630349557002.blob.core.windows.net/3630349557/innetagmgmt-dynamic-pvc-9ca1d804-7014-11e8-ac80-000d3ab45bd1.vhd
    Kind:         Shared
    FSType:       ext4
    CachingMode:  ReadWrite
    ReadOnly:     false
Events:           <none>

The VM-Size is:
Standard DS2 (2 vcpus, 7 GB memory)

[andyzhangx]

@mausquirk the disk actually attached to pod successfully, I could see following errors from your pods:

[Entrypoint] MySQL Docker Image 5.7.21-1.1.3
[Entrypoint] Initializing database
2018-06-14T20:59:11.481713Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-06-14T20:59:11.484034Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
2018-06-14T20:59:11.484087Z 0 [ERROR] Aborting 

It looks like failure is due to there are files under /var/lib/mysql, disk format will create DATALOSS_WARNING_README.txt under that dir, would you use subPath instead? (it will create a new directory in the newly attached azure disk)

        volumeMounts:
        -  mountPath: /var/lib/mysql
           subPath: data
           name: acousticity-generic-mysql-pstorage

[mausquirk]

I expected the volume to be as clean as a tarn in the Swiss Alps!!
I tried to mount the volume from my computer to verify this, but gave up due to the big download size (1GB).

Targeting the DB-data into the subPath did fix it! Thanks!

Is there a tool, to check a Page-Blob's content online?
BTW: What's written in this DATALOSS_WARNING_README.txt-File?

[andyzhangx]

@mausquirk I was wrong, there should be a lost+found directory.

You don't need to download that blob disk, you could detach and attach to a running VM, and mount that disk into a dir to check content.

[mausquirk]

Thanks. That works.