cluster-provision.log

+ source /opt/azure/containers/provision_source.sh
++ cat /etc/lsb-release /etc/os-release
++ awk '{print toupper($0)}'
++ tr -d 'ID="'
++ grep '^ID='
+ OS=UBUNTU
+ UBUNTU_OS_NAME=UBUNTU
+ RHEL_OS_NAME=RHEL
+ COREOS_OS_NAME=COREOS
+ KUBECTL=/usr/local/bin/kubectl
+ DOCKER=/usr/bin/docker
+ set +x
+ [[ UBUNTU == COREOS ]]
++ date
++ hostname
+ echo Wed Apr 4 00:25:17 UTC 2018,k8s-master-31213958-0, startscript
+ '[' -f /var/run/reboot-required ']'
+ REBOOTREQUIRED=false
+ [[ ! -z true ]]
+ echo 'executing master node provision operations'
executing master node provision operations
+ useradd -U etcd
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
++ head -c 32 /dev/urandom
++ base64
+ usermod -p 9uqW1o0qbJRVFdejxkvBUlVvdXQ5ETEu4JgKBhAEPuE= etcd
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
+ passwd -u etcd
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
sent invalidate(passwd) request, exiting
sent invalidate(group) request, exiting
passwd: password expiry information changed.
+ id etcd
uid=1001(etcd) gid=1001(etcd) groups=1001(etcd)
++ date
++ hostname
+ echo Wed Apr 4 00:25:17 UTC 2018,k8s-master-31213958-0, beginGettingEtcdCerts
+ APISERVER_PRIVATE_KEY_PATH=/etc/kubernetes/certs/apiserver.key
+ touch /etc/kubernetes/certs/apiserver.key
+ chmod 0600 /etc/kubernetes/certs/apiserver.key
+ chown root:root /etc/kubernetes/certs/apiserver.key
+ CA_PRIVATE_KEY_PATH=/etc/kubernetes/certs/ca.key
+ touch /etc/kubernetes/certs/ca.key
+ chmod 0600 /etc/kubernetes/certs/ca.key
+ chown root:root /etc/kubernetes/certs/ca.key
+ ETCD_SERVER_PRIVATE_KEY_PATH=/etc/kubernetes/certs/etcdserver.key
+ touch /etc/kubernetes/certs/etcdserver.key
+ chmod 0600 /etc/kubernetes/certs/etcdserver.key
+ chown etcd:etcd /etc/kubernetes/certs/etcdserver.key
+ ETCD_CLIENT_PRIVATE_KEY_PATH=/etc/kubernetes/certs/etcdclient.key
+ touch /etc/kubernetes/certs/etcdclient.key
+ chmod 0600 /etc/kubernetes/certs/etcdclient.key
+ chown root:root /etc/kubernetes/certs/etcdclient.key
+ ETCD_PEER_PRIVATE_KEY_PATH=/etc/kubernetes/certs/etcdpeer0.key
+ touch /etc/kubernetes/certs/etcdpeer0.key
+ chmod 0600 /etc/kubernetes/certs/etcdpeer0.key
+ chown etcd:etcd /etc/kubernetes/certs/etcdpeer0.key
+ ETCD_SERVER_CERTIFICATE_PATH=/etc/kubernetes/certs/etcdserver.crt
+ touch /etc/kubernetes/certs/etcdserver.crt
+ chmod 0644 /etc/kubernetes/certs/etcdserver.crt
+ chown root:root /etc/kubernetes/certs/etcdserver.crt
+ ETCD_CLIENT_CERTIFICATE_PATH=/etc/kubernetes/certs/etcdclient.crt
+ touch /etc/kubernetes/certs/etcdclient.crt
+ chmod 0644 /etc/kubernetes/certs/etcdclient.crt
+ chown root:root /etc/kubernetes/certs/etcdclient.crt
+ ETCD_PEER_CERTIFICATE_PATH=/etc/kubernetes/certs/etcdpeer0.crt
+ touch /etc/kubernetes/certs/etcdpeer0.crt
+ chmod 0644 /etc/kubernetes/certs/etcdpeer0.crt
+ chown root:root /etc/kubernetes/certs/etcdpeer0.crt
+ set +x
++ date
++ hostname
+ echo Wed Apr 4 00:25:18 UTC 2018,k8s-master-31213958-0, endGettingEtcdCerts
+ mkdir -p /opt/azure/containers
+ touch /opt/azure/containers/certs.ready
+ KUBELET_PRIVATE_KEY_PATH=/etc/kubernetes/certs/client.key
+ touch /etc/kubernetes/certs/client.key
+ chmod 0600 /etc/kubernetes/certs/client.key
+ chown root:root /etc/kubernetes/certs/client.key
+ APISERVER_PUBLIC_KEY_PATH=/etc/kubernetes/certs/apiserver.crt
+ touch /etc/kubernetes/certs/apiserver.crt
+ chmod 0644 /etc/kubernetes/certs/apiserver.crt
+ chown root:root /etc/kubernetes/certs/apiserver.crt
+ AZURE_JSON_PATH=/etc/kubernetes/azure.json
+ touch /etc/kubernetes/azure.json
+ chmod 0600 /etc/kubernetes/azure.json
+ chown root:root /etc/kubernetes/azure.json
+ set +x
+ [[ docker == \c\l\e\a\r\-\c\o\n\t\a\i\n\e\r\s ]]
+ [[ UBUNTU == UBUNTU ]]
+ apt-mark hold walinuxagent
walinuxagent set on hold.
++ date
++ hostname
+ echo Wed Apr 4 00:25:18 UTC 2018,k8s-master-31213958-0, EnsureDockerStart
+ ensureDockerInstallCompleted
+ echo 'waiting for docker install to finish'
waiting for docker install to finish
+ for i in '{1..900}'
+ '[' -e /opt/azure/containers/dockerinstall.complete ']'
+ sleep 1
...
+ for i in '{1..900}'
+ '[' -e /opt/azure/containers/dockerinstall.complete ']'
+ echo 'docker install finished, took 48 seconds'
docker install finished, took 48 seconds
+ break
+ ensureDocker
+ systemctlEnableAndCheck docker
+ systemctl enable docker
Synchronizing state of docker.service with SysV init with /lib/systemd/systemd-sysv-install...
Executing /lib/systemd/systemd-sysv-install enable docker
+ systemctl is-enabled docker
enabled
+ enabled=0
+ for i in '{1..900}'
+ '[' 0 -ne 0 ']'
+ echo 'docker took 1 seconds to be enabled by systemctl'
docker took 1 seconds to be enabled by systemctl
+ break
+ '[' 0 -ne 0 ']'
+ false
+ dockerStarted=1
+ for i in '{1..900}'
+ /usr/bin/docker info
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 0
Server Version: 1.13.1
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: aa8187dbd3b7ad67d8e5e3a15115d3eef43a7ed1
runc version: 9df8b306d01f59d3a8029be411de015b7304dd8f
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.13.0-1011-azure
Operating System: Ubuntu 16.04.3 LTS
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 6.785 GiB
Name: k8s-master-31213958-0
ID: PTVV:5DF2:XFMU:HWQQ:DBAP:EUIO:VSVA:G6ZV:XA2T:VLVW:AAZH:DT7N
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: true
+ echo 'docker started, took 1 seconds'
docker started, took 1 seconds
+ dockerStarted=0
+ break
+ '[' 0 -ne 0 ']'
++ date
++ hostname
+ echo Wed Apr 4 00:26:07 UTC 2018,k8s-master-31213958-0, configNetworkPolicyStart
+ configNetworkPolicy
+ [[ azure = \a\z\u\r\e ]]
+ configAzureNetworkPolicy
+ CNI_CONFIG_DIR=/etc/cni/net.d
+ mkdir -p /etc/cni/net.d
+ chown -R root:root /etc/cni/net.d
+ chmod 755 /etc/cni/net.d
+ CNI_BIN_DIR=/opt/cni/bin
+ mkdir -p /opt/cni/bin
+ AZURE_CNI_TGZ_TMP=/tmp/azure_cni.tgz
+ retrycmd_if_failure_no_stats 180 1 curl -fsSL https://acs-mirror.azureedge.net/cni/azure-vnet-cni-linux-amd64-v1.0.2.tgz
+ retries=180
+ wait=1
+ shift
+ shift
++ seq 1 180
+ for i in '$(seq 1 $retries)'
+ curl -fsSL https://acs-mirror.azureedge.net/cni/azure-vnet-cni-linux-amd64-v1.0.2.tgz
+ '[' 0 -eq 0 ']'
+ break
+ tar -xzf /tmp/azure_cni.tgz -C /opt/cni/bin
+ CONTAINERNETWORKING_CNI_TGZ_TMP=/tmp/containernetworking_cni.tgz
+ retrycmd_if_failure_no_stats 180 1 curl -fsSL https://acs-mirror.azureedge.net/cni/cni-plugins-amd64-v0.7.0.tgz
+ retries=180
+ wait=1
+ shift
+ shift
++ seq 1 180
+ for i in '$(seq 1 $retries)'
+ curl -fsSL https://acs-mirror.azureedge.net/cni/cni-plugins-amd64-v0.7.0.tgz
+ '[' 0 -eq 0 ']'
+ break
+ tar -xzf /tmp/containernetworking_cni.tgz -C /opt/cni/bin ./loopback ./portmap
+ chown -R root:root /opt/cni/bin
+ chmod -R 755 /opt/cni/bin
+ mv /opt/cni/bin/10-azure.conflist /etc/cni/net.d/
+ chmod 600 /etc/cni/net.d/10-azure.conflist
+ /sbin/ebtables -t nat --list
Bridge table: nat

Bridge chain: PREROUTING, entries: 0, policy: ACCEPT

Bridge chain: OUTPUT, entries: 0, policy: ACCEPT

Bridge chain: POSTROUTING, entries: 0, policy: ACCEPT
+ configCNINetworkPolicy
+ setNetworkPlugin cni
+ sed -i 's/^KUBELET_NETWORK_PLUGIN=.*/KUBELET_NETWORK_PLUGIN=cni/' /etc/default/kubelet
+ setDockerOpts ' --volume=/etc/cni/:/etc/cni:ro --volume=/opt/cni/:/opt/cni:ro'
+ sed -i 's#^DOCKER_OPTS=.*#DOCKER_OPTS= --volume=/etc/cni/:/etc/cni:ro --volume=/opt/cni/:/opt/cni:ro#' /etc/default/kubelet
+ [[ docker == \c\l\e\a\r\-\c\o\n\t\a\i\n\e\r\s ]]
++ date
++ hostname
+ echo Wed Apr 4 00:26:17 UTC 2018,k8s-master-31213958-0, setMaxPodsStart
+ setMaxPods 30
+ sed -i 's/^KUBELET_MAX_PODS=.*/KUBELET_MAX_PODS=30/' /etc/default/kubelet
++ date
++ hostname
+ echo Wed Apr 4 00:26:17 UTC 2018,k8s-master-31213958-0, ensureCRIOStart
+ ensureCRIO
+ [[ docker == \c\l\e\a\r\-\c\o\n\t\a\i\n\e\r\s ]]
++ date
++ hostname
+ echo Wed Apr 4 00:26:17 UTC 2018,k8s-master-31213958-0, ensureKubeletStart
+ ensureKubelet
+ retrycmd_if_failure 100 1 docker pull k8s-gcrio.azureedge.net/hyperkube-amd64:v1.10.0
+ retries=100
+ wait=1
+ shift
+ shift
++ seq 1 100
+ for i in '$(seq 1 $retries)'
+ docker pull k8s-gcrio.azureedge.net/hyperkube-amd64:v1.10.0
v1.10.0: Pulling from hyperkube-amd64
d0c199d1a37e: Pulling fs layer
9eea4969cc0f: Pulling fs layer
e25b982f4e4f: Pulling fs layer
39668194e1b9: Pulling fs layer
259521fecfa9: Pulling fs layer
7c5dab2ec3a4: Pulling fs layer
bc886847eb0d: Pulling fs layer
7f40224f2596: Pulling fs layer
39668194e1b9: Waiting
259521fecfa9: Waiting
7c5dab2ec3a4: Waiting
bc886847eb0d: Waiting
7f40224f2596: Waiting
e25b982f4e4f: Verifying Checksum
e25b982f4e4f: Download complete
9eea4969cc0f: Verifying Checksum
9eea4969cc0f: Download complete
39668194e1b9: Verifying Checksum
39668194e1b9: Download complete
d0c199d1a37e: Verifying Checksum
d0c199d1a37e: Download complete
bc886847eb0d: Verifying Checksum
bc886847eb0d: Download complete
7c5dab2ec3a4: Verifying Checksum
7c5dab2ec3a4: Download complete
7f40224f2596: Verifying Checksum
7f40224f2596: Download complete
259521fecfa9: Verifying Checksum
259521fecfa9: Download complete
d0c199d1a37e: Pull complete
9eea4969cc0f: Pull complete
e25b982f4e4f: Pull complete
39668194e1b9: Pull complete
259521fecfa9: Pull complete
7c5dab2ec3a4: Pull complete
bc886847eb0d: Pull complete
7f40224f2596: Pull complete
Digest: sha256:898d145786fb66532cb66223c5d3b270010c0da48c013cd97326808a8eca980a
Status: Downloaded newer image for k8s-gcrio.azureedge.net/hyperkube-amd64:v1.10.0
+ '[' 0 -eq 0 ']'
+ break
+ echo Executed '"docker' pull 'k8s-gcrio.azureedge.net/hyperkube-amd64:v1.10.0"' 1 times
Executed "docker pull k8s-gcrio.azureedge.net/hyperkube-amd64:v1.10.0" 1 times
+ systemctlEnableAndCheck kubelet
+ systemctl enable kubelet
Created symlink from /etc/systemd/system/multi-user.target.wants/kubelet.service to /etc/systemd/system/kubelet.service.
+ systemctl is-enabled kubelet
enabled
+ enabled=0
+ for i in '{1..900}'
+ '[' 0 -ne 0 ']'
+ echo 'kubelet took 1 seconds to be enabled by systemctl'
kubelet took 1 seconds to be enabled by systemctl
+ break
+ '[' 0 -ne 0 ']'
+ false
+ systemctl restart kubelet
++ date
++ hostname
+ echo Wed Apr 4 00:27:17 UTC 2018,k8s-master-31213958-0, extractKubctlStart
+ extractKubectl
+ systemctlEnableAndCheck kubectl-extract
+ systemctl enable kubectl-extract
Created symlink from /etc/systemd/system/multi-user.target.wants/kubectl-extract.service to /etc/systemd/system/kubectl-extract.service.
+ systemctl is-enabled kubectl-extract
enabled
+ enabled=0
+ for i in '{1..900}'
+ '[' 0 -ne 0 ']'
+ echo 'kubectl-extract took 1 seconds to be enabled by systemctl'
kubectl-extract took 1 seconds to be enabled by systemctl
+ break
+ '[' 0 -ne 0 ']'
+ false
+ systemctl restart kubectl-extract
++ date
++ hostname
+ echo Wed Apr 4 00:27:20 UTC 2018,k8s-master-31213958-0, ensureJournalStart
+ ensureJournal
+ systemctl daemon-reload
+ systemctlEnableAndCheck systemd-journald.service
+ systemctl enable systemd-journald.service
+ systemctl is-enabled systemd-journald.service
static
+ enabled=0
+ for i in '{1..900}'
+ '[' 0 -ne 0 ']'
+ echo 'systemd-journald.service took 1 seconds to be enabled by systemctl'
systemd-journald.service took 1 seconds to be enabled by systemctl
+ break
+ '[' 0 -ne 0 ']'
+ echo Storage=persistent
+ echo SystemMaxUse=1G
+ echo RuntimeMaxUse=1G
+ echo ForwardToSyslog=no
+ false
+ systemctl restart systemd-journald.service
++ date
++ hostname
+ echo Wed Apr 4 00:27:21 UTC 2018,k8s-master-31213958-0, ensureJournalDone
+ ensureRunCommandCompleted
+ echo 'waiting for runcmd to finish'
waiting for runcmd to finish
+ for i in '{1..900}'
+ '[' -e /opt/azure/containers/runcmd.complete ']'
+ sleep 1
...
+ echo 'runcmd finished, took 31 seconds'
runcmd finished, took 31 seconds
+ break
++ date
++ hostname
+ echo Wed Apr 4 00:27:51 UTC 2018,k8s-master-31213958-0, RunCmdCompleted
+ [[ ! -z true ]]
+ writeKubeConfig
+ KUBECONFIGDIR=/home/azureuser1/.kube
+ KUBECONFIGFILE=/home/azureuser1/.kube/config
+ mkdir -p /home/azureuser1/.kube
+ touch /home/azureuser1/.kube/config
+ chown azureuser1:azureuser1 /home/azureuser1/.kube
+ chown azureuser1:azureuser1 /home/azureuser1/.kube/config
+ chmod 700 /home/azureuser1/.kube
+ chmod 600 /home/azureuser1/.kube/config
+ set +x
+ ensureFilepath /usr/local/bin/kubectl
+ false
+ found=1
+ for i in '{1..600}'
+ '[' -e /usr/local/bin/kubectl ']'
+ found=0
+ echo '/usr/local/bin/kubectl is present, took 1 seconds to verify'
/usr/local/bin/kubectl is present, took 1 seconds to verify
+ break
+ '[' 0 -ne 0 ']'
+ ensureFilepath /usr/bin/docker
+ false
+ found=1
+ for i in '{1..600}'
+ '[' -e /usr/bin/docker ']'
+ found=0
+ echo '/usr/bin/docker is present, took 1 seconds to verify'
/usr/bin/docker is present, took 1 seconds to verify
+ break
+ '[' 0 -ne 0 ']'
+ ensureEtcdDataDir
+ grep /var/lib/etcddisk
+ grep /dev/sdc1
+ mount
/dev/sdc1 on /var/lib/etcddisk type ext4 (rw,relatime,data=ordered)
+ '[' 0 = 0 ']'
+ echo 'Etcd is running with data dir at: /var/lib/etcddisk'
Etcd is running with data dir at: /var/lib/etcddisk
+ return
+ ensureEtcd
+ etcdIsRunning=1
+ for i in '{1..600}'
+ curl --cacert /etc/kubernetes/certs/ca.crt --cert /etc/kubernetes/certs/etcdclient.crt --key /etc/kubernetes/certs/etcdclient.key --max-time 60 https://127.0.0.1:2379/v2/machines
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
100    25  100    25    0     0    195      0 --:--:-- --:--:-- --:--:--   196
https://10.255.255.5:2379+ '[' 0 -eq 0 ']'
+ etcdIsRunning=0
+ echo 'Etcd setup successfully, took 1 seconds'
Etcd setup successfully, took 1 seconds
+ break
+ '[' 0 -ne 0 ']'
+ ensureK8s
+ false
+ k8sHealthy=1
+ nodesActive=1
+ nodesReady=1
+ for i in '{1..600}'
+ '[' -e /usr/local/bin/kubectl ']'
+ break
+ for i in '{1..600}'
+ /usr/local/bin/kubectl cluster-info
Kubernetes master is running at http://localhost:8080

To further debug and diagnose cluster problems, use 'kubectl cluster-info dump'.
+ '[' 1 = 0 ']'
+ sleep 1
+ for i in '{1..600}'
+ /usr/local/bin/kubectl cluster-info
Kubernetes master is running at http://localhost:8080
...
To further debug and diagnose cluster problems, use 'kubectl cluster-info dump'.
+ '[' 0 = 0 ']'
+ echo 'k8s cluster is healthy, took 36 seconds'
k8s cluster is healthy, took 36 seconds
+ k8sHealthy=0
+ break
+ '[' 0 -ne 0 ']'
+ for i in '{1..1800}'
++ /usr/local/bin/kubectl get nodes
++ grep Ready
++ wc -l
+ nodes=2
+ '[' 2 -eq 4 ']'
+ sleep 1
# Here it waits f or 49 minutes and 16 seconds
+ echo 'still waiting for active nodes after 1800 seconds'
still waiting for active nodes after 1800 seconds
+ exit 3