juju bootstrap silently fails to bootstrap on localhost Bad configuration option: pubkeyacceptedalgorithms

[Bartosz Woronicz]

Cannot connect to the bootstrapped local machine in lxd, only after adding --debug it reveals the issue
17:03:59 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.91 failed: /home/mastier/.ssh/config: line 30: Bad configuration option: pubkeyacceptedalgorithms

The actual option that it complains

$ sed -n '30p' .ssh/config
    PubkeyAcceptedAlgorithms +ssh-rsa

Don't understand why this is a problem for juju bootstrap and why actually it is checked

To reproduce try the following on Jammy

$ snap install juju --channel 3.2/stable

$ snap info juju|grep installed
installed: 3.2.0 (23190) 80MB -

$ juju --debug bootstrap
16:48:47 INFO juju.cmd supercommand.go:56 running juju [3.2.0 c7107ada8c471aa3ba105e5433e61861227e2ed4 gc go1.20.4]
16:48:47 DEBUG juju.cmd supercommand.go:57 args: []string{"/snap/juju/23190/bin/juju", "--debug", "bootstrap"}
16:48:47 DEBUG juju.environs.tools build.go:122 looking for: /snap/juju/23190/bin/juju
16:48:47 DEBUG juju.environs.tools versionfile.go:54 looking for sha256 dd91f1e8fb0f19322549106f6c6793513358485bc9951a73b30b32b7a642d3b1
16:48:47 DEBUG juju.kubernetes.provider detectcloud.go:33 failed to query local microk8s: "/var/snap/juju/23190/microk8s/credentials/client.config" does not exist: juju "3.2.0" can only work with strictly confined microk8s
Clouds
aws
aws-china
aws-gov
azure
azure-china
equinix
google
localhost
oracle

Select a cloud [localhost]:

16:48:49 DEBUG juju.environs.tools build.go:122 looking for: /snap/juju/23190/bin/juju
16:48:49 DEBUG juju.environs.tools versionfile.go:54 looking for sha256 dd91f1e8fb0f19322549106f6c6793513358485bc9951a73b30b32b7a642d3b1
16:48:49 DEBUG juju.kubernetes.provider detectcloud.go:33 failed to query local microk8s: "/var/snap/juju/23190/microk8s/credentials/client.config" does not exist: juju "3.2.0" can only work with strictly confined microk8s
Enter a name for the Controller [localhost-localhost]:
16:48:50 DEBUG juju.container.lxd connection.go:179 using LXD socket at path: "/var/snap/lxd/common/lxd/unix.socket"
16:48:50 INFO cmd provider.go:328 Resolved LXD host address on bridge lxdbr0: https://10.18.61.1:8443
16:48:50 INFO cmd cloudcredential.go:47 updating credential store
16:48:50 DEBUG juju.cmd.juju.commands bootstrap.go:1392 authenticating with region "localhost" and credential "localhost" ()
16:48:50 DEBUG juju.cmd.juju.commands bootstrap.go:1551 provider attrs: map[project:default]
16:48:50 INFO cmd authkeys.go:113 Adding contents of "/home/mastier/.local/share/juju/ssh/juju_id_rsa.pub" to authorized-keys
16:48:50 INFO cmd authkeys.go:113 Adding contents of "/home/mastier/.ssh/id_rsa.pub" to authorized-keys
16:48:50 DEBUG juju.cmd.juju.commands bootstrap.go:1621 preparing controller with config: map[agent-metadata-url: agent-stream:released apt-ftp-proxy: apt-http-proxy: apt-https-proxy: apt-mirror: apt-no-proxy: authorized-keys:ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDBtVA4BcRPyQJr2SfVXoPhMNO4tc95ou4wabXdNleN/v41k5HUids0zQ6vkLi9HTk9ZWDchcKMJK+KmhlKIz7BK8OL70fdiJefT1DPFjKmUfOLPuzjujk084ufTPyuLF31Vet6uGH5bvu6QCpRF/0UsiiJ9uedUBZXKY4W2Ozy9OSvvJDnRSy3sQsZf7U3vGwMM7a6jRbE/bLT9m9g+u46mCA1jCdR+JbnxTNEME19DwmVXA90ldNsGkdS3DccLjsceidakD2RVCBU9hfzHNZ+JqfDaKLGcOdTc9nlrECI1OgNh3a6imdcf3Yf7RXZ64trnO+VyqezN6ffawjRZnILXNVd0b3eY78Ja9Luerzky9lBFRz8S30/2IIMIafkjPSe2mG7OExPDqH5Yyd6PDM00EAd6lbJwCJ+V4u6blqggqlqJhfqNt34tbDFapUyoN/p5A1V4KdrsJjxJ9g4msVFe19d0dXAwlmmFMfMjyaztDtEL8J1NNzq1oZYaE6fh1bFr+1YZAZ7WfQWpuaqwfojrIVW6bX/tNkA8SEXMU1/5hwjXT/dELmuuPYT25FgswfAE4uWhWeM2MNzoHHJgF8Y3lKmZm8ylD5UXoIEnYY2hLKYVyZuTVFC/IMJwZ/qpLYPSUe8mo+hQ6x+49ij5Lqnps8MBMqKOQhILewlkDYdGQ== juju-client-key
ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDntDTrULqVQMaAzYOsSn/EGq0xDw9bX0umpEfoAUvz+wy0sW5FLNM0xASIftqCxEiUV1Qm+MPhy8EKOWMo9m4e6VGLsFsjeye/P6iBTz/sdfsdfz25QULLwqYnkj7TBpPnhI6oeWKnbp8GKPQroxXxpDDBneqk7u+tKh4xf6QCoCY9gj0/1ATaUJ2GVBf55JC9/nZBTJSdYVW9bZ7/EWXLsE4WUhfpAAV8xtsiMsIGrIfuupL5pgJ4vPXLpV6kre2y4FmuCqvEDGc8yCkGz2sPFJiHBsrGc8YU1LstoLdekRl9n3YuVsviRlSc0XxUb/Cm7PtlTxwm11Nc+34tO54LUuIgsAd/FXm8= mastier@myhost
 automatically-retry-hooks:true backup-dir: charmhub-url:https://api.charmhub.io cloudinit-userdata: container-image-metadata-url: container-image-stream:released container-inherit-properties: container-networking-method: default-base: default-space: development:false disable-network-management:false disable-telemetry:false egress-subnets: enable-os-refresh-update:true enable-os-upgrade:true fan-config: firewall-mode:instance ftp-proxy: http-proxy: https-proxy: ignore-machine-addresses:false image-metadata-url: image-stream:released juju-ftp-proxy: juju-http-proxy: juju-https-proxy: juju-no-proxy:127.0.0.1,localhost,::1 logforward-enabled:false logging-config: logging-output: lxd-snap-channel:5.0/stable max-action-results-age:336h max-action-results-size:5G max-status-history-age:336h max-status-history-size:5G mode:requires-prompts name:controller net-bond-reconfigure-delay:17 no-proxy:127.0.0.1,localhost,::1 num-container-provision-workers:4 num-provision-workers:16 project:default provisioner-harvest-mode:destroyed proxy-ssh:false resource-tags: saas-ingress-allow:0.0.0.0/0,::/0 secret-backend:auto snap-http-proxy: snap-https-proxy: snap-store-assertions: snap-store-proxy: snap-store-proxy-url: ssh-allow:0.0.0.0/0,::/0 ssl-hostname-verification:true test-mode:false transmit-vendor-metrics:true type:lxd update-status-hook-interval:5m uuid:dba74ef9-a3cf-4a97-8912-866e23703038]
16:48:50 INFO cmd bootstrap.go:939 Creating Juju controller "localhost-localhost" on localhost/localhost
16:48:50 INFO juju.cmd.juju.commands bootstrap.go:1010 combined bootstrap constraints:
16:48:50 DEBUG juju.environs.bootstrap bootstrap.go:319 model "controller" supports application/machine networks: true
16:48:50 DEBUG juju.environs.bootstrap bootstrap.go:321 network management by juju enabled: true
16:48:50 DEBUG juju.environs.bootstrap bootstrap.go:374 auto-selecting bootstrap arch "amd64"
16:48:50 INFO cmd bootstrap.go:402 Loading image metadata
16:48:50 INFO cmd bootstrap.go:468 Looking for packaged Juju agent version 3.2.0 for amd64
16:48:50 INFO juju.environs.bootstrap tools.go:78 looking for bootstrap agent binaries: version=3.2.0
16:48:50 DEBUG juju.environs.tools tools.go:87 finding agent binaries in stream: "released"
16:48:50 DEBUG juju.environs.tools tools.go:89 reading agent binaries with major.minor version 3.2
16:48:50 DEBUG juju.environs.tools tools.go:98 filtering agent binaries by version: 3.2.0
16:48:50 DEBUG juju.environs.tools tools.go:101 filtering agent binaries by os type: ubuntu
16:48:50 DEBUG juju.environs.tools tools.go:104 filtering agent binaries by architecture: amd64
16:48:50 DEBUG juju.environs.tools urls.go:133 trying datasource "keystone catalog"
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:417 searching for signed metadata in datasource "default simplestreams"
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:451 looking for data index using path streams/v1/index2.sjson
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:747 using default candidate for content id "com.ubuntu.juju:released:agents" are {20210329 mirrors:1.0 content-download streams/v1/cpc-mirrors-agents.sjson []}
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:463 looking for data index using URL https://streams.canonical.com/juju/tools/streams/v1/index2.sjson
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:486 read metadata index at "https://streams.canonical.com/juju/tools/streams/v1/index2.sjson"
16:48:50 DEBUG juju.environs.simplestreams simplestreams.go:1018 finding products at path "streams/v1/com.ubuntu.juju-released-agents.sjson"
16:48:50 INFO juju.environs.bootstrap tools.go:80 found 1 packaged agent binaries
16:48:50 INFO cmd bootstrap.go:481 Located Juju agent version 3.2.0-ubuntu-amd64 at https://streams.canonical.com/juju/tools/agent/3.2.0/juju-3.2.0-linux-amd64.tgz
16:48:50 INFO cmd bootstrap.go:579 Starting new instance for initial controller
16:48:50 INFO cmd environ.go:219 To configure your system to better support LXD containers, please see: https://linuxcontainers.org/lxd/docs/master/explanation/performance_tuning/
16:48:50 INFO cmd bootstrap.go:187 Launching controller instance(s) on localhost/localhost...
16:48:50 DEBUG juju.provider.lxd environ_broker.go:33 StartInstance: "0", ubuntu@22.04/stable
16:48:50 DEBUG juju.cloudconfig.instancecfg instancecfg.go:947 Setting numa ctl preference to false
16:48:50 DEBUG juju.environs imagemetadata.go:119 obtained image datasource "default ubuntu cloud images"
16:48:50 DEBUG juju.container.lxd connection.go:196 LXD requires https://, using: https://cloud-images.ubuntu.com/releases/
16:48:50 DEBUG juju.container.lxd image.go:64 Found image locally - "" "a0a9b9976255e7235afe495e920e6c0f40f55ae22852a5d5c31139aa9408f2e5"
16:48:50 DEBUG juju.provider.lxd environ_broker.go:235 LXD user data; 4780 bytes
16:48:50 INFO juju.container.lxd container.go:294 starting new container "juju-703038-0" (image "")
16:48:50 DEBUG juju.container.lxd container.go:295 new container has profiles [default juju-controller]
16:48:52 DEBUG juju.container.lxd container.go:326 created container "juju-703038-0", waiting for start...
16:48:53 INFO juju.provider.lxd environ_broker.go:48 started instance "juju-703038-0"
16:48:53 INFO cmd bootstrap.go:331 - juju-703038-0 (arch=amd64)
16:48:53 INFO juju.environs.bootstrap bootstrap.go:999 newest version: 3.2.0
16:48:53 INFO juju.environs.bootstrap bootstrap.go:1014 picked bootstrap agent binary version: 3.2.0
16:48:53 INFO cmd bootstrap.go:622 Installing Juju agent on bootstrap instance
16:48:53 DEBUG juju.cloudconfig.instancecfg instancecfg.go:947 Setting numa ctl preference to false
Waiting for address
Attempting to connect to 10.18.61.91:22
Attempting to connect to fd42:3e71:9632:c147:216:3eff:fe90:7d2:22
16:49:03 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe90:7d2 failed: /home/mastier/.ssh/config: line 30: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: line 37: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: line 58: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: terminating, 3 bad configuration options

[Bartosz Woronicz (mastier1)]

Also having to the ControlMaster active, cause inability to connect.

If someone got these options in their .ssh/config is unable to bootstrap juju controller.

Host *
  ControlPath ~/.ssh/%r@%h
  ControlPersist 57600
  ControlMaster yes

17:17:41 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe2a:44a8 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@fd42:3e71:9632:c147:216:3eff:fe2a:44a8.UEYeYMcncnOCJ9yX: Permission denied
17:17:41 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.55 failed: unix_listener: cannot bind to path /home/mastier/.ssh/[e-mail]6TzsiEIv6: Permission denied
17:17:46 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.55 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@10.18.61.55.W8vnW6M6fZCoCib9: Permission denied
17:17:46 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe2a:44a8 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@fd42:3e71:9632:c147:216:3eff:fe2a:44a8.BE3nRmp2kckxsxTx: Permission denied
17:17:51 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe2a:44a8 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@fd42:3e71:9632:c147:216:3eff:fe2a:44a8.5RsnNDAOofW0ehnk: Permission denied
17:17:51 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.55 failed: unix_listener: cannot bind to path /home/mastier/.ssh/[e-mail]: Permission denied
17:17:56 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.55 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@10.18.61.55.P46mpX9c7EPQle8c: Permission denied
17:17:56 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe2a:44a8 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@fd42:3e71:9632:c147:216:3eff:fe2a:44a8.U8y9ztSW64jsBDpN: Permission denied
17:18:01 DEBUG juju.provider.common bootstrap.go:686 connection attempt for fd42:3e71:9632:c147:216:3eff:fe2a:44a8 failed: unix_listener: cannot bind to path /home/mastier/.ssh/ubuntu@fd42:3e71:9632:c147:216:3eff:fe2a:44a8.oDsZpfb66B1fap27: Permission denied
17:18:01 DEBUG juju.provider.common bootstrap.go:686 connection attempt for 10.18.61.55 failed: unix_listener: cannot bind to path /home/mastier/.ssh/[e-mail]97WURDcpj2r5S: Permission denied
17:18:06 DEBUG juju.provider.common bootstrap.go:686 co

[Bartosz Woronicz (mastier1)]

This happens also when just trying to ssh to unit on the host with such ssh config

mastier@drakkar:~/work/canonical$ juju ssh ceph-mon/0
/home/mastier/.ssh/config: line 30: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: line 37: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: line 58: Bad configuration option: pubkeyacceptedalgorithms
/home/mastier/.ssh/config: terminating, 3 bad configuration options

[John A Meinel (jameinel)]

My best guess is that your host's OpenSSH supports "pubkeyacceptedalgorithms" in its .ssh/config, but the one that juju ships inside the confined snap does not.

To verify this, you could try to do:
ssh ubuntu@10.18.61.55

And see whether the host's ssh is happy, but then do:
snap run --shell juju
$$ type -a ssh
ssh is /snap/juju/23846/usr/bin/ssh
...
$$ ssh ubuntu@10.18.61.55

And see whether the confined ssh is unhappy with that ssh configuration.

Certainly the expectation is that we cannot do much about
   ControlPath ~/.ssh/%r@%h

Because it is very likely that snap confinement means that processes running inside the confined Juju snap cannot access the custom directories that are supplied by your ssh config.

I was able to reproduce that on my jammy machine:
$ cat ~/.ssh/config

Host 10.25.164.32
        PubkeyAcceptedAlgorithms +ssh-rsa

$ juju ssh controller/0
/home/jameinel/.ssh/config: line 3: Bad configuration option: pubkeyacceptedalgorithms
/home/jameinel/.ssh/config: terminating, 1 bad configuration options

$ ssh ubuntu@10.25.164.32
# is happy

$ ssh -V
OpenSSH_8.9p1 Ubuntu-3ubuntu0.3, OpenSSL 3.0.2 15 Mar 2022
$ snap run --shell juju
$$ ssh -V
OpenSSH_8.2p1 Ubuntu-4ubuntu0.8, OpenSSL 1.1.1f 31 Mar 2020

So Jammy is shipping ssh 8.9, but Juju is bundling 8.2. We should almost certainly update that.

[John A Meinel (jameinel)]

In snap/snapcraft.yaml we seem to just be doing:
    stage-packages:
      - openssh-client

Maybe the issue is that we are doing:
base: core20

I can say that 8.2 is from Focal, and 8.9 would be from Jammy:
https://packages.ubuntu.com/focal/openssh-client
https://packages.ubuntu.com/jammy/openssh-client

[Joseph Phillips (manadart)]

Triaged, but no milestone assigned. Are there implications for upgrading the base across point releases?

I assume not, because we went from core18 to core20 last year on the 2.9 branch.

[Vitaly Antonenko (anvial)]

To fix this bug we need to switch the base to core22, but in current moment is’t impossible. The reason is:
”local plugin support is not currently available for core22. To use local v2 plugins you need to stay in core20 until we have this functionality properly redesigned.”

Source: https://forum.snapcraft.io/t/local-v2-plugin-base-core22/32227

And we need to use local plugin `juju-go`.

[John A Meinel (jameinel)]

While reproducing this, there is still one issue that is quite important. Namely, we don't report any errors to the user while this is happening.

Specifically, I went to reproduce this bug, tweaked my config, forgot about it when I came back 1 week later, and the issue is that we report *0* warnings or failures except at debug level.

So `juju bootstrap lxd lxd` under this situation just sits there and fails, and after 20 minutes comes back with 'failed to bootstrap', and kills your instances. There is also nothing in cloud-init-output.log (because the failure is client side.)

I think at a minimum we should be trying to surface this error:
```
09:12:41 DEBUG juju.provider.common bootstrap.go:669 connection attempt for 10.8.158.125 failed: /home/jameinel/.ssh/config: line 3: Bad configuration option: pubkeyacceptedalgorithms
/home/jameinel/.ssh/config: terminating, 1 bad configuration options
```

I know that the reason we don't surface SSH errors by default is because we *expect* that the controller won't be up immediately, and so we don't want to scare users by saying that we failed to connect.

But we need something that can take a "I think I can retry this error, but I have been retrying it for 1 minute, I should surface something".

Note that the error that we explicitly want to supress are these:
09:18:46 DEBUG juju.provider.common bootstrap.go:669 connection attempt for 10.8.158.251 failed: ssh: connect to host 10.8.158.251 port 22: Connection refused

09:18:52 DEBUG juju.provider.common bootstrap.go:669 connection attempt for 10.8.158.251 failed: /var/lib/juju/nonce.txt does not exist

Those are both cases where the machine hasn't finished initializing, and it is a race condition between the client trying to connect and the machine not being done with cloud-init.

But "terminating, 1 bad configuration options" is a permanent failure that needs human intervention.