ceph rbd dynamic provision report: Could not map image: Timeout after 10s

[AncientRemember]

kubernetes v1.4.3:

Environment:

• centos 7
• docker 1.12
  -hyperkube1.4.3

i follow the example :https://github.com/kubernetes/kubernetes/tree/master/examples/experimental/persistent-volume-provisioning/rbd
to deploy a rbd pvc,but encounter a error:
Operation for ""kubernetes.io/rbd/27398ce7-a579-11e6-8b62-7427ea3303cf-pvc-1424170c-a577-11e6-8b62-7427ea3303cf" ("27398ce7-a579-11e6-8b62-7427ea3303cf")" failed. No retries permitted until 2016-11-08 06:10:17.31506197 +0000 UTC (durationBeforeRetry 2m0s). Error: MountVolume.SetUp failed for volume "kubernetes.io/rbd/27398ce7-a579-11e6-8b62-7427ea3303cf-pvc-1424170c-a577-11e6-8b62-7427ea3303cf" (spec.Name: "pvc-1424170c-a577-11e6-8b62-7427ea3303cf") pod "27398ce7-a579-11e6-8b62-7427ea3303cf" (UID: "27398ce7-a579-11e6-8b62-7427ea3303cf") with: Could not map image: Timeout after 10s

How to reproduce it :
apiVersion: storage.k8s.io/v1beta1
kind: StorageClass
metadata:
name: slow
provisioner: kubernetes.io/rbd
parameters:
monitors: xxx.xxx.xxx.xxxx:6789
adminId: admin
adminSecretName: ceph-secret-admin
pool: kube
userId: admin
userSecretName: ceph-secret-admin

kind: PersistentVolumeClaim
apiVersion: v1
metadata:
name: myclaim
annotations:
volume.beta.kubernetes.io/storage-class: "slow"
spec:
accessModes:
- ReadWriteOnce
resources:
requests:
storage: 8Gi

apiVersion: v1
kind: Secret
metadata:
name: ceph-secret-admin
data:
key: QVFBVVF4QllVQmNuSVJBQUdwc3NZNkYzWmlnaUp3WUJDS3lSSlE9PQ==

kind: Pod
apiVersion: v1
metadata:
name: mypod
spec:
containers:
- name: myfrontend
image: dockerfile/nginx
volumeMounts:
- mountPath: "/var/www/html"
name: mypd
volumes:
- name: mypd
persistentVolumeClaim:
claimName: myclaim

[AncientRemember]

i have install ceph and ceph common in the hyperkube,and add kubelete mount
-v /var/lib/docker:/var/lib/docker:rw
-v /sbin/modprobe:/sbin/modprobe:ro
-v /lib/modules:/lib/modules:ro
-v /etc/ceph:/etc/ceph:ro \

[AncientRemember]

this is the kubelet log:
I1108 06:09:47.722977 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:09:57.795834 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:09:57.795856 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:00.292477 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/rbd/27398a8a-a579-11e6-8b62-7427ea3303cf-pvc-1424170c-a577-11e6-8b62-7427ea3303cf" (spec.Name: "pvc-1424170c-a577-11e6-8b62-7427ea3303cf") to pod "27398a8a-a579-11e6-8b62-7427ea3303cf" (UID: "27398a8a-a579-11e6-8b62-7427ea3303cf").
I1108 06:10:01.325219 12317 rbd_util.go:234] rbd: map mon 192.168.29.10:6789
I1108 06:10:05.058460 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:05.058485 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:05.106590 12317 server.go:968] GET /stats/summary/: (95.946473ms) 200 [[Go-http-client/1.1] 10.1.14.3:43294]
I1108 06:10:07.853502 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:07.853528 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
E1108 06:10:11.770650 12317 disk_manager.go:61] failed to attach disk
E1108 06:10:11.770679 12317 rbd.go:393] rbd: failed to setup mount /var/lib/kubelet/pods/27398a8a-a579-11e6-8b62-7427ea3303cf/volumes/kubernetes.io~rbd/pvc-1424170c-a577-11e6-8b62-7427ea3303cf Could not map image: Timeout after 10s
E1108 06:10:11.770813 12317 nestedpendingoperations.go:253] Operation for ""kubernetes.io/rbd/27398a8a-a579-11e6-8b62-7427ea3303cf-pvc-1424170c-a577-11e6-8b62-7427ea3303cf" ("27398a8a-a579-11e6-8b62-7427ea3303cf")" failed. No retries permitted until 2016-11-08 06:12:11.77077201 +0000 UTC (durationBeforeRetry 2m0s). Error: MountVolume.SetUp failed for volume "kubernetes.io/rbd/27398a8a-a579-11e6-8b62-7427ea3303cf-pvc-1424170c-a577-11e6-8b62-7427ea3303cf" (spec.Name: "pvc-1424170c-a577-11e6-8b62-7427ea3303cf") pod "27398a8a-a579-11e6-8b62-7427ea3303cf" (UID: "27398a8a-a579-11e6-8b62-7427ea3303cf") with: Could not map image: Timeout after 10s
I1108 06:10:14.193563 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07ce8d54-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07ce8d54-a570-11e6-8b62-7427ea3303cf" (UID: "07ce8d54-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:14.492993 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07ce8d54-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07ce8d54-a570-11e6-8b62-7427ea3303cf" (UID: "07ce8d54-a570-11e6-8b62-7427ea3303cf").
I1108 06:10:17.894849 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:17.895248 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:20.192788 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/06ee90cb-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "06ee90cb-a570-11e6-8b62-7427ea3303cf" (UID: "06ee90cb-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:20.293023 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/06ee90cb-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "06ee90cb-a570-11e6-8b62-7427ea3303cf" (UID: "06ee90cb-a570-11e6-8b62-7427ea3303cf").
I1108 06:10:21.179338 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/078f6589-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "078f6589-a570-11e6-8b62-7427ea3303cf" (UID: "078f6589-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:21.293316 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/078f6589-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "078f6589-a570-11e6-8b62-7427ea3303cf" (UID: "078f6589-a570-11e6-8b62-7427ea3303cf").
I1108 06:10:25.192519 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/078c976d-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "078c976d-a570-11e6-8b62-7427ea3303cf" (UID: "078c976d-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:25.292799 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/078c976d-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "078c976d-a570-11e6-8b62-7427ea3303cf" (UID: "078c976d-a570-11e6-8b62-7427ea3303cf").
I1108 06:10:27.985772 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:27.985794 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:28.193027 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/070dd979-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "070dd979-a570-11e6-8b62-7427ea3303cf" (UID: "070dd979-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:28.493019 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/070dd979-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "070dd979-a570-11e6-8b62-7427ea3303cf" (UID: "070dd979-a570-11e6-8b62-7427ea3303cf").
E1108 06:10:30.032221 12317 kubelet.go:1356] Unable to mount volumes for pod "redis-zbk54_default(27398a8a-a579-11e6-8b62-7427ea3303cf)": timeout expired waiting for volumes to attach/mount for pod "redis-zbk54"/"default". list of unattached/unmounted volumes=[data]; skipping pod
E1108 06:10:30.032442 12317 pod_workers.go:184] Error syncing pod 27398a8a-a579-11e6-8b62-7427ea3303cf, skipping: timeout expired waiting for volumes to attach/mount for pod "redis-zbk54"/"default". list of unattached/unmounted volumes=[data]
I1108 06:10:38.047741 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:38.047793 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:42.094294 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/27398a8a-a579-11e6-8b62-7427ea3303cf-default-token-s1xzg" (spec.Name: "default-token-s1xzg") to pod "27398a8a-a579-11e6-8b62-7427ea3303cf" (UID: "27398a8a-a579-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:42.293169 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/27398a8a-a579-11e6-8b62-7427ea3303cf-default-token-s1xzg" (spec.Name: "default-token-s1xzg") pod "27398a8a-a579-11e6-8b62-7427ea3303cf" (UID: "27398a8a-a579-11e6-8b62-7427ea3303cf").
I1108 06:10:45.200399 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/1a51e923-a571-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "1a51e923-a571-11e6-8b62-7427ea3303cf" (UID: "1a51e923-a571-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:45.295158 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/1a51e923-a571-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "1a51e923-a571-11e6-8b62-7427ea3303cf" (UID: "1a51e923-a571-11e6-8b62-7427ea3303cf").
I1108 06:10:48.134496 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:48.134515 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:56.092524 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07c1bdee-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07c1bdee-a570-11e6-8b62-7427ea3303cf" (UID: "07c1bdee-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:56.292997 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07c1bdee-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07c1bdee-a570-11e6-8b62-7427ea3303cf" (UID: "07c1bdee-a570-11e6-8b62-7427ea3303cf").
I1108 06:10:58.219757 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:58.219780 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:10:59.292966 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07cf55fb-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07cf55fb-a570-11e6-8b62-7427ea3303cf" (UID: "07cf55fb-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:10:59.492884 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07cf55fb-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07cf55fb-a570-11e6-8b62-7427ea3303cf" (UID: "07cf55fb-a570-11e6-8b62-7427ea3303cf").
I1108 06:11:05.080963 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:11:05.080990 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:11:05.106431 12317 server.go:968] GET /stats/summary/: (90.614319ms) 200 [[Go-http-client/1.1] 10.1.14.3:43294]
I1108 06:11:08.230152 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:11:08.230210 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:11:11.192632 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07ceb9bc-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07ceb9bc-a570-11e6-8b62-7427ea3303cf" (UID: "07ceb9bc-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:11:11.692938 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07ceb9bc-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07ceb9bc-a570-11e6-8b62-7427ea3303cf" (UID: "07ceb9bc-a570-11e6-8b62-7427ea3303cf").
I1108 06:11:16.192694 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07761aad-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07761aad-a570-11e6-8b62-7427ea3303cf" (UID: "07761aad-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:11:16.492998 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07761aad-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07761aad-a570-11e6-8b62-7427ea3303cf" (UID: "07761aad-a570-11e6-8b62-7427ea3303cf").
I1108 06:11:17.192712 12317 reconciler.go:300] MountVolume operation started for volume "kubernetes.io/secret/07ce8d54-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") to pod "07ce8d54-a570-11e6-8b62-7427ea3303cf" (UID: "07ce8d54-a570-11e6-8b62-7427ea3303cf"). Volume is already mounted to pod, but remount was requested.
I1108 06:11:17.492895 12317 operation_executor.go:802] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/07ce8d54-a570-11e6-8b62-7427ea3303cf-default-token-3ufwo" (spec.Name: "default-token-3ufwo") pod "07ce8d54-a570-11e6-8b62-7427ea3303cf" (UID: "07ce8d54-a570-11e6-8b62-7427ea3303cf").
I1108 06:11:18.271575 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats
I1108 06:11:18.271740 12317 conversion.go:133] failed to handle multiple devices for container. Skipping Filesystem stats

[jingxu97]

cc @kubernetes/sig-storage

[rootfs]

this looks a slow rbd map, @AncientRemember can you run rbd map manually and see how long it takes?

[AncientRemember]

i have fixed this isssu,by reinstall ceph,and make sure i can manually map the rbd image,thanks At 2016-12-01 07:34:12, "Huamin Chen" <notifications@github.com> wrote: this looks a slow rbd map, @AncientRemember can you run rbd map manually and see how long it takes? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[jingxu97]

@AncientRemember great! close this issue now and please let us know if you have any other issue.