Canonical Juju

[microk8s] juju stuck bootstrapping controller

Bug #1933848 reported by Dariusz Smigiel on 2021-06-28

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Canonical Juju	Expired	Undecided	Unassigned

Bug Description

During the process of bootstrapping controller on microk8s, it hung.
Simple payload works on microk8s (logs below the report)

dasm@dell:~/git/charm-opensearch-k8s$ snap list | grep -E "juju|microk8s"
juju 2.9.5 16559 latest/stable canonical* classic
microk8s v1.20.7 2264 1.20/stable canonical* classic

[...]
07:58:57 DEBUG juju.kubernetes.provider rbac.go:220 service account "controller" created
07:58:57 DEBUG juju.kubernetes.provider bootstrap.go:828 creating controller statefulset:
&StatefulSet{ObjectMeta:{controller controller-majkro 0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[app.kubernetes.io/managed-by:juju app.kubernetes.io/name:controller model.juju.is/disable-webhook:true] map[controller.juju.is/id:1041ee35-2562-460f-803f-ee182d31b5ec] [] [] []},Spec:StatefulSetSpec{Replicas:*1,Selector:&v1.LabelSelector{MatchLabels:map[string]string{app.kubernetes.io/name: controller,},MatchExpressions:[]LabelSelectorRequirement{},},Template:{{controller-0 controller-majkro 0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[app.kubernetes.io/name:controller model.juju.is/disable-webhook:true] map[controller.juju.is/id:1041ee35-2562-460f-803f-ee182d31b5ec] [] [] []} {[{controller-server-pem {nil nil nil nil nil SecretVolumeSource{SecretName:controller-secret,Items:[]KeyToPath{KeyToPath{Key:server.pem,Path:template-server.pem,Mode:nil,},},DefaultMode:*256,Optional:nil,} nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil}} {controller-shared-secret {nil nil nil nil nil &SecretVolumeSource{SecretName:controller-secret,Items:[]KeyToPath{KeyToPath{Key:shared-secret,Path:shared-secret,Mode:nil,},},DefaultMode:*256,Optional:nil,} nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil}} {controller-agent-conf {nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil &ConfigMapVolumeSource{LocalObjectReference:LocalObjectReference{Name:controller-configmap,},Items:[]KeyToPath{KeyToPath{Key:agent.conf,Path:template-agent.conf,Mode:nil,},},DefaultMode:nil,Optional:nil,} nil nil nil nil nil nil nil nil nil nil}} {controller-bootstrap-params {nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil &ConfigMapVolumeSource{LocalObjectReference:LocalObjectReference{Name:controller-configmap,},Items:[]KeyToPath{KeyToPath{Key:bootstrap-params,Path:bootstrap-params,Mode:nil,},},DefaultMode:nil,Optional:nil,} nil nil nil nil nil nil nil nil nil nil}}] [] [{mongodb jujusolutions/juju-db:4.0 [mongod] [--dbpath=/var/lib/juju/db --sslPEMKeyFile=/var/lib/juju/server.pem --sslPEMKeyPassword=ignored --sslMode=requireSSL --port=37017 --journal --replSet=juju --quiet --oplogSize=1024 --ipv6 --auth --keyFile=/var/lib/juju/shared-secret --storageEngine=wiredTiger --bind_ip_all] [{mongodb 0 37017 TCP }] [] [] {map[memory:{{1610612736 0} {<nil>} BinarySI}] map[]} [{storage false /var/lib/juju <nil> } {storage false /var/lib/juju/db db <nil> } {controller-server-pem true /var/lib/juju/template-server.pem template-server.pem <nil> } {controller-shared-secret true /var/lib/juju/shared-secret shared-secret <nil> }] [] &Probe{Handler:Handler{Exec:&ExecAction{Command:[mongo --port=37017 --ssl --sslAllowInvalidHostnames --sslAllowInvalidCertificates --sslPEMKeyFile=/var/lib/juju/server.pem --eval db.adminCommand('ping')],},HTTPGet:nil,TCPSocket:nil,},InitialDelaySeconds:30,TimeoutSeconds:5,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:3,} &Probe{Handler:Handler{Exec:&ExecAction{Command:[mongo --port=37017 --ssl --sslAllowInvalidHostnames --sslAllowInvalidCertificates --sslPEMKeyFile=/var/lib/juju/server.pem --eval db.adminCommand('ping')],},HTTPGet:nil,TCPSocket:nil,},InitialDelaySeconds:5,TimeoutSeconds:1,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:3,} nil nil IfNotPresent nil false false false} {api-server jujusolutions/jujud-operator:2.9.5 [/bin/sh] [-c export JUJU_DATA_DIR=/var/lib/juju
export JUJU_TOOLS_DIR=$JUJU_DATA_DIR/tools

mkdir -p $JUJU_TOOLS_DIR
cp /opt/jujud $JUJU_TOOLS_DIR/jujud

echo Installing Dashboard...
export gui='/var/lib/juju/gui'
mkdir -p $gui
curl -sSf -o $gui/gui.tar.bz2 --retry 10 --noproxy 127.0.0.1,localhost,::1 'https://streams.canonical.com/juju/gui/gui/0.7.1/juju-dashboard-0.7.1.tar.bz2' || echo Unable to retrieve Juju Dashboard
[ -f $gui/gui.tar.bz2 ] && sha256sum $gui/gui.tar.bz2 > $gui/jujugui.sha256
[ -f $gui/jujugui.sha256 ] && (grep '514734ad8eaf3d1aaad9600a84253cac6e504dbdf8e1eb610d9a1155c1c9d516' $gui/jujugui.sha256 && printf %s '{"version":"0.7.1","url":"https://streams.canonical.com/juju/gui/gui/0.7.1/juju-dashboard-0.7.1.tar.bz2","sha256":"514734ad8eaf3d1aaad9600a84253cac6e504dbdf8e1eb610d9a1155c1c9d516","size":1770516}' > $gui/downloaded-gui.txt || echo Juju GUI checksum mismatch)
test -e $JUJU_DATA_DIR/agents/controller-0/agent.conf || $JUJU_TOOLS_DIR/jujud bootstrap-state $JUJU_DATA_DIR/bootstrap-params --data-dir $JUJU_DATA_DIR --debug --timeout 20m0s
$JUJU_TOOLS_DIR/jujud machine --data-dir $JUJU_DATA_DIR --controller-id 0 --log-to-stderr --debug
] /var/lib/juju [] [] [] {map[memory:{{1610612736 0} {<nil>} BinarySI}] map[]} [{storage false /var/lib/juju <nil> } {controller-agent-conf false /var/lib/juju/agents/controller-0/template-agent.conf template-agent.conf <nil> } {controller-server-pem true /var/lib/juju/template-server.pem template-server.pem <nil> } {controller-shared-secret true /var/lib/juju/shared-secret shared-secret <nil> } {controller-bootstrap-params true /var/lib/juju/bootstrap-params bootstrap-params <nil> }] [] nil nil nil nil IfNotPresent nil false false false}] [] Always <nil> <nil> map[] controller 0xc000ade4bc false false false <nil> nil [] nil [] [] <nil> nil [] <nil> <nil> <nil> map[] [] <nil>}},VolumeClaimTemplates:[]PersistentVolumeClaim{{{ } {storage 0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[app.kubernetes.io/managed-by:juju app.kubernetes.io/name:controller] map[controller.juju.is/id:1041ee35-2562-460f-803f-ee182d31b5ec] [] [] []} {[ReadWriteOnce] nil {map[] map[storage:{{21474836480 0} {<nil>} 20Gi BinarySI}]} 0xc00000b6e0 <nil> nil} { [] map[] []}},},ServiceName:controller-service,PodManagementPolicy:,UpdateStrategy:StatefulSetUpdateStrategy{Type:,RollingUpdate:nil,},RevisionHistoryLimit:nil,},Status:StatefulSetStatus{ObservedGeneration:0,Replicas:0,ReadyReplicas:0,CurrentReplicas:0,UpdatedReplicas:0,CurrentRevision:,UpdateRevision:,CollisionCount:nil,Conditions:[]StatefulSetCondition{},},}
07:58:57 DEBUG juju.kubernetes.provider k8s.go:2142 selecting units "app.kubernetes.io/name=controller" to watch
07:58:57 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
07:58:58 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
07:58:58 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller
07:58:58 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
07:58:58 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:00:13 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:00:13 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
08:01:13 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:01:13 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
08:02:43 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:02:43 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
08:03:43 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:03:43 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
08:04:43 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:04:43 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
08:05:43 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
08:05:43 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"

-----
microk8s payload

dasm@dell:~/git/charm-opensearch-k8s$ microk8s kubectl get all
NAME READY STATUS RESTARTS AGE
pod/microbot-5f5499d479-59xns 1/1 Running 0 10m
pod/microbot-5f5499d479-8v52f 1/1 Running 0 10m

NAME TYPE CLUSTER-IP EXTERNAL-IP PORT(S) AGE
service/kubernetes ClusterIP 10.152.183.1 <none> 443/TCP 13m
service/microbot-service NodePort 10.152.183.242 <none> 80:32011/TCP 10m

NAME READY UP-TO-DATE AVAILABLE AGE
deployment.apps/microbot 2/2 2 2 10m

NAME DESIRED CURRENT READY AGE
replicaset.apps/microbot-5f5499d479 2 2 2 10m
dasm@dell:~/git/charm-opensearch-k8s$ curl 10.152.183.242
<!DOCTYPE html>
<html>
  <style type="text/css">
    .centered
      {
      text-align:center;
      margin-top:0px;
      margin-bottom:0px;
      padding:0px;
      }
  </style>
  <body>
    <p class="centered"><img src="microbot.png" alt="microbot"/></p>
    <p class="centered">Container hostname: microbot-5f5499d479-8v52f</p>
  </body>
</html>

Revision history for this message

Dariusz Smigiel (smigiel-dariusz) wrote on 2021-06-28:

Download full text (3.3 KiB)

After a while it continues with

08:18:57 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=storage-controller-0,involvedObject.kind=PersistentVolumeClaim"
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:367 bootstrap failed, removing 8 resources.
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:594 deleting "controller-service"
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:648 deleting "controller-secret" shared-secret
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:669 deleting "controller-secret" server.pem
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:696 deleting "controller-configmap" bootstrap-params
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:718 deleting "controller-configmap" template-agent.conf
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:741 deleting "controller" service account
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:772 deleting "controller-majkro" cluster role binding
08:18:57 DEBUG juju.kubernetes.provider bootstrap.go:830 deleting "controller" statefulset
08:18:57 ERROR juju.cmd.juju.commands bootstrap.go:883 failed to bootstrap model: creating controller stack: creating statefulset for controller: timed out waiting for controller pod: unschedulable: pvc storage-controller-0 pending due to ExternalProvisioning - waiting for a volume to be created, either by external provisioner "microk8s.io/hostpath" or manually created by system administrator
08:18:57 DEBUG juju.cmd.juju.commands bootstrap.go:884 (error details: [{/build/snapcraft-juju-35d6cf/parts/juju/src/cmd/juju/commands/bootstrap.go:983: failed to bootstrap model} {/build/snapcraft-juju-35d6cf/parts/juju/src/environs/bootstrap/bootstrap.go:667: } {/build/snapcraft-juju-35d6cf/parts/juju/src/environs/bootstrap/bootstrap.go:298: } {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/k8s.go:436: creating controller stack} {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/bootstrap.go:465: creating statefulset for controller} {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/bootstrap.go:846: } {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/bootstrap.go:980: timed out waiting for controller pod} {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/bootstrap.go:930: unschedulable} {/build/snapcraft-juju-35d6cf/parts/juju/src/caas/kubernetes/provider/bootstrap.go:910: pvc storage-controller-0 pending due to ExternalProvisioning - waiting for a volume to be created, either by external provisioner "microk8s.io/hostpath" or manually created by system administrator}])
08:18:57 DEBUG juju.cmd.juju.commands bootstrap.go:1634 cleaning up after failed bootstrap
08:18:58 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-majkro
08:18:58 DEBUG juju.kubernetes.provider teardown.go:282 namespace "controller-majkro" is still been terminating
08:18:59 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-majkro
08:18:59 DEBUG juju.kubernetes.provider teardown.go:282 namespace "controller-majkro" is still been termina...

FWIW, after going back to microk8s 1.18/stable it worked

10:04:24 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:04:24 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:04:27 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller
10:04:27 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:04:27 DEBUG juju.kubernetes.provider bootstrap.go:884 Successfully assigned controller-mk8s/controller-0 to dell
10:04:27 DEBUG juju.kubernetes.provider bootstrap.go:884 Downloading images
10:04:27 INFO  cmd bootstrap.go:886 Downloading images
10:04:27 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:04:27 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:04:44 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:04:44 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:04:44 DEBUG juju.kubernetes.provider bootstrap.go:884 Pulled images
10:04:45 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:04:45 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:04:45 DEBUG juju.kubernetes.provider bootstrap.go:884 Created container mongodb
10:04:45 DEBUG juju.kubernetes.provider bootstrap.go:884 Started mongodb container
10:05:36 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:05:36 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:05:40 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller-0
10:05:40 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:05:40 DEBUG juju.kubernetes.provider bootstrap.go:884 Created container api-server
10:05:40 DEBUG juju.kubernetes.provider bootstrap.go:884 Started controller container
10:05:41 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller-0,involvedObject.kind=Pod"
10:05:41 DEBUG juju.kubernetes.provider.watcher k8swatcher.go:115 fire notify watcher for controller
10:05:41 INFO  cmd bootstrap.go:972 Starting controller pod
10:05:41 INFO  cmd bootstrap.go:669 Bootstrap agent now started
10:05:41 DEBUG juju.kubernetes.provider events.go:52 getting the latest event for "involvedObject.name=controller,involvedObject.kind=StatefulSet"
10:05:41 INFO  juju.juju api.go:330 API endpoints changed from [] to [10.152.183.8:17070]
10:05:41 INFO  cmd controller.go:93 Contacting Juju controller at 10.152.183.8 to verify accessibility...
10:05:41 INFO  juju.juju api.go:78 connecting to API addresses: [10.152.183.8:17070]
10:06:15 DEBUG juju.api apiclient.go:618 starting proxier for connection
10:06:15 DEBUG juju.api apiclient.go:622 tunnel proxy in use at localhost on port 42459
10:06:15 INFO  juju.api apiclient.go:1051 cannot resolve "localhost": i/o timeout
10:06:15 INFO  cmd controller.go:135 Still waiting for API to become available: cannot resolve "localhost": i/o timeout
10:06:15 INFO  juju.juju api.go:78 connecting to API addresses: [10.152.183.8:17070]
10:06:15 DEBUG juju.api apiclient.go:618 starting proxier for connection
10:06:15 DEBUG juju.api apiclient.go:622 tunnel proxy in use at localhost on port 46447
10:06:15 DEBUG juju.api apiclient.go:802 looked up localhost -> [127.0.0.1]
10:06:15 DEBUG juju.api apiclient.go:1149 successfully dialed "wss://localhost:46447/model/b417a53f-3c81-48fd-81c7-c304581ea333/api"
10:06:15 INFO  juju.api apiclient.go:680 connection established to "wss://localhost:46447/model/b417a53f-3c81-48fd-81c7-c304581ea333/api"
10:06:15 DEBUG juju.api monitor.go:35 RPC connection died
10:06:15 INFO  cmd controller.go:104 
Bootstrap complete, controller "mk8s" is now available in namespace "controller-mk8s"
10:06:15 INFO  cmd bootstrap.go:595 
Now you can run
	juju add-model <model-name>
to create a new model to deploy k8s workloads.
10:06:15 INFO  cmd supercommand.go:544 command finished
dasm@dell:~/git/charm-opensearch-k8s$

Revision history for this message

Vitaly Antonenko (anvial) wrote on 2022-02-23:

Is this problem still actual in 2.9.22?

I try to reproduce the bug on my microk8s, but the bootstrap process passes without any error.

Changed in juju:
status:	New → Incomplete

Revision history for this message

Launchpad Janitor (janitor) wrote on 2022-04-25:

[Expired for juju because there has been no activity for 60 days.]

Changed in juju:
status:	Incomplete → Expired

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.