BootstrapSuite.TestAutoUploadAfterFailedSync times out intermittently

[Tim Penhey]

FAIL github.com/juju/juju/cmd/juju/commands 622.727s

FAIL: bootstrap_test.go:1323: BootstrapSuite.TestAutoUploadAfterFailedSync

[LOG] 0:00.010 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.011 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.011 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.019 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.019 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.019 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.053 INFO cmd no credentials found, checking environment
[LOG] 0:00.053 DEBUG juju.cmd.juju.commands authenticating with region "region-1" and credential "default" ()
[LOG] 0:00.053 DEBUG juju.cmd.juju.commands provider attrs: map[broken: controller:false secret:pork]
[LOG] 0:07.549 INFO cmd Adding contents of "/tmp/juju-unittestfs/jj-489/check-8038222006122339127/8/.ssh/id_rsa.pub" to authorized-keys
[LOG] 0:07.550 DEBUG juju.cmd.juju.commands 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:public auth key
 automatically-retry-hooks:true backup-dir: broken: cloudinit-userdata: container-image-metadata-url: container-image-stream:released container-inherit-properties: container-networking-method: controller:false default-series:raring default-space: development:false disable-network-management: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: lxd-snap-channel:latest/stable max-action-results-age:336h max-action-results-size:5G max-status-history-age:336h max-status-history-size:5G name:controller net-bond-reconfigure-delay:17 no-proxy:127.0.0.1,localhost,::1 provisioner-harvest-mode:destroyed proxy-ssh:false resource-tags: secret:pork snap-http-proxy: snap-https-proxy: snap-store-assertions: snap-store-proxy: snap-store-proxy-url: ssl-hostname-verification:true test-mode:false transmit-vendor-metrics:true type:dummy update-status-hook-interval:5m uuid:a990fe6b-74ac-400e-87cf-2a84cf980eb0]
[LOG] 0:07.551 INFO juju.cmd.juju.commands combined bootstrap constraints:
[LOG] 0:07.551 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
[LOG] 0:07.551 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:07.551 INFO cmd Loading image metadata
[LOG] 0:07.551 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=<nil>
[LOG] 0:07.551 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:07.551 DEBUG juju.environs.tools reading agent binaries with major.minor version 1.7
[LOG] 0:07.551 DEBUG juju.environs.tools filtering agent binaries by series: raring
[LOG] 0:07.551 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:07.551 DEBUG juju.environs.tools trying datasource "keystone catalog"
[LOG] 0:07.552 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/jj-489/check-8038222006122339127/10/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:07.552 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/jj-489/check-8038222006122339127/10/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:07.554 INFO juju.environs.bootstrap found 0 packaged agent binaries
[LOG] 0:07.555 DEBUG juju.environs.sync Making agent binary tarball
[LOG] 0:07.555 INFO juju.environs.sync using agent binary 1.7.3-raring-amd64 aliased to 1.7.3.1-raring-amd64 (0kB)
[LOG] 0:07.555 INFO cmd Starting new instance for initial controller
[LOG] 0:07.555 INFO juju.provider.dummy would pick agent binaries from 1.7.3.1-raring-amd64
[LOG] 0:07.555 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:07.555 INFO juju.environs.bootstrap newest version: 1.7.3.1
[LOG] 0:07.555 INFO juju.environs.bootstrap picked bootstrap agent binary version: 1.7.3.1
bootstrap_test.go:1337:
    c.Fatal("timed out")
... Error: timed out

[LOG] 0:10.098 INFO juju.provider.dummy reset model
[LOG] 0:10.098 DEBUG juju.provider.dummy resetting MgoServer
[LOG] 0:10.105 INFO juju.testing reset successfully reset admin password
[LOG] 0:10.125 INFO juju.testing reset successfully reset admin password

Something is going on there that is taking 7.5 seconds. This is perhaps a keygen, which we could look to simplify for the test to speed it up.

[Joseph Phillips (manadart)]

As far as I can tell, there is no keygen occurring between the indicative log lines - it's only file system access to read the key files.

This appears to be an issue with the tempfs that we create in an attempt to speed up the tests. I looks like this is also the source of the various time-outs when waiting for container addresses and such.

[Tim Penhey (thumper)]

https://usercontent.irccloud-cdn.com/file/ceDs66KD/out.png (not sure how
long that lives)

Effectively from bootstrap.NewConfig and
bootstrap.finalizeInstanceBootstrapConfig we are calling into pki.RSA3072.

This is where the time seems to be being spent.

On Tue, May 12, 2020 at 7:50 PM Joseph Phillips <email address hidden>
wrote:

> As far as I can tell, there is no keygen occurring between the
> indicative log lines - it's only file system access to read the key
> files.
>
> This appears to be an issue with the tempfs that we create in an attempt
> to speed up the tests. I looks like this is also the source of the
> various time-outs when waiting for container addresses and such.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1878135
>
> Title:
> BootstrapSuite.TestAutoUploadAfterFailedSync times out intermittently
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1878135/+subscriptions
>

[Tim Penhey (thumper)]

Another occurrence

FAIL: bootstrap_test.go:1323: BootstrapSuite.TestAutoUploadAfterFailedSync

[LOG] 0:00.022 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.022 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.022 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.036 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.037 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.037 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.048 INFO cmd no credentials found, checking environment
[LOG] 0:00.048 DEBUG juju.cmd.juju.commands authenticating with region "region-1" and credential "default" ()
[LOG] 0:00.048 DEBUG juju.cmd.juju.commands provider attrs: map[broken: controller:false secret:pork]
[LOG] 0:04.399 INFO cmd Adding contents of "/tmp/juju-unittestfs/jj-dZD/check-9157533353687561143/8/.ssh/id_rsa.pub" to authorized-keys
[LOG] 0:04.399 DEBUG juju.cmd.juju.commands 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:public auth key
 automatically-retry-hooks:true backup-dir: broken: cloudinit-userdata: container-image-metadata-url: container-image-stream:released container-inherit-properties: container-networking-method: controller:false default-series:raring default-space: development:false disable-network-management: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: lxd-snap-channel:latest/stable max-action-results-age:336h max-action-results-size:5G max-status-history-age:336h max-status-history-size:5G name:controller net-bond-reconfigure-delay:17 no-proxy:127.0.0.1,localhost,::1 provisioner-harvest-mode:destroyed proxy-ssh:false resource-tags: secret:pork snap-http-proxy: snap-https-proxy: snap-store-assertions: snap-store-proxy: snap-store-proxy-url: ssl-hostname-verification:true test-mode:false transmit-vendor-metrics:true type:dummy update-status-hook-interval:5m uuid:eec61e36-0d3a-45ad-867c-a3cf0726e1ee]
[LOG] 0:04.400 INFO juju.cmd.juju.commands combined bootstrap constraints:
[LOG] 0:04.400 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
[LOG] 0:04.400 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:04.400 INFO cmd Loading image metadata
[LOG] 0:04.400 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=<nil>
[LOG] 0:04.400 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:04.400 DEBUG juju.environs.tools reading agent binaries with major.minor version 1.7
[LOG] 0:04.400 DEBUG juju.environs.tools filtering agent binaries by series: raring
[LOG] 0:04.400 DEBUG juju.environs.tools filtering agent bin...

[Canonical Juju QA Bot (juju-qa-bot)]

This bug has not been updated in 2 years, so we're marking it Low importance. If you believe this is incorrect, please update the importance.