Canonical Juju

Intermittent test failure: cannot upload charm ... not a valid zip file

Bug #1788401 reported by Simon Richardson on 2018-08-22

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Canonical Juju	Triaged	Low	Unassigned

Bug Description

There is an intermittent test failure inside of client_macaroon_test.go: clientMacaroonSuite.TestAddLocalCharmSuccess

It fails on CI and I've been unable to replicate it locally.

----------------------------------------------------------------------
FAIL: client_macaroon_test.go:61: clientMacaroonSuite.TestAddLocalCharmSuccess

[LOG] 0:00.006 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.006 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-bionic-amd64
[LOG] 0:00.007 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-precise-amd64
[LOG] 0:00.008 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-trusty-amd64
[LOG] 0:00.013 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-xenial-amd64
[LOG] 0:00.016 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.016 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.016 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.024 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.024 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-bionic-amd64
[LOG] 0:00.024 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-precise-amd64
[LOG] 0:00.025 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-trusty-amd64
[LOG] 0:00.027 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-xenial-amd64
[LOG] 0:00.031 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-4875426175978810514/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.031 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-4875426175978810514/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.031 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-4875426175978810514/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.036 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.036 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.036 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.058 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
[LOG] 0:00.058 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.058 INFO cmd Loading image metadata
[LOG] 0:00.058 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=2.5-beta1
[LOG] 0:00.058 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:00.058 DEBUG juju.environs.tools reading agent binaries with major.minor version 2.5
[LOG] 0:00.058 DEBUG juju.environs.tools filtering agent binaries by version: 2.5-beta1
[LOG] 0:00.058 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:00.066 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-4875426175978810514/5/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:00.067 INFO juju.environs.bootstrap found 4 packaged agent binaries
[LOG] 0:00.067 INFO cmd Starting new instance for initial controller
[LOG] 0:00.067 INFO juju.provider.dummy would pick agent binaries from 2.5-beta1-bionic-amd64
[LOG] 0:00.067 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.067 INFO juju.environs.bootstrap newest version: 2.5-beta1
[LOG] 0:00.067 INFO juju.environs.bootstrap picked bootstrap agent binary version: 2.5-beta1
[LOG] 0:00.085 DEBUG juju.cloudconfig.instancecfg Setting numa ctl preference to false
[LOG] 0:00.086 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.155 DEBUG juju.state mongodb initialised
[LOG] 0:00.155 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.156 INFO juju.state running state anonymously; using unique store id
[LOG] 0:00.156 INFO juju.state starting standard state workers
[LOG] 0:00.156 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.156 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.156 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.156 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.156 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.156 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.156 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.172 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.172 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.319 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
[LOG] 0:00.323 DEBUG juju.centralhub created subscriber 0xc420dead20 for 0xc63950
[LOG] 0:00.324 WARNING juju.apiserver.logsink Unable to prime /tmp/juju-unittestfs/check-4875426175978810514/4/logsink.log (proceeding anyway): chown /tmp/juju-unittestfs/check-4875426175978810514/4/logsink.log: operation not permitted
[LOG] 0:00.324 DEBUG juju.centralhub created subscriber 0xc420b58b40 for 0xc63950
[LOG] 0:00.330 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.352 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.376 INFO juju.state starting standard state workers
[LOG] 0:00.376 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.376 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.377 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.377 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.377 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.377 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.400 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:39273"
[LOG] 0:00.422 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.424 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.436 DEBUG juju.api successfully dialed "wss://localhost:34947/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.436 INFO juju.api connection established to "wss://localhost:34947/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.441 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.441 DEBUG juju.apiserver model login: user-admin for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.443 DEBUG juju.state setting apiHostPorts: [[localhost:34947]]
[LOG] 0:00.443 DEBUG juju.state setting apiHostPortsForAgents: [[localhost:34947]]
[LOG] 0:00.505 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.506 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.514 DEBUG juju.api successfully dialed "wss://localhost:34947/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.514 INFO juju.api connection established to "wss://localhost:34947/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.521 INFO juju.apiserver login failed with discharge-required error: verification failed: macaroon not found in storage
[LOG] 0:00.521 DEBUG httpbakery postFormJSON to https://127.0.0.1:36084/discharge; vals: url.Values{"id":[]string{"eyJUaGlyZFBhcnR5UHVibGljS2V5IjoieVo2OGdDMUd3SVZsMWJrM0h1Rk1Ld0hpNzZsTHZvUzBkU0w2Q0lhNnJ5ST0iLCJGaXJzdFBhcnR5UHVibGljS2V5IjoiZ3hxM2o1WS9LdGNXRWhZRG84WGdTUFdaTVFGNVl0cFV4blpMcSszcGQyST0iLCJOb25jZSI6IkRVMjdnRUdmYi9jRWR6d3VFUkZWOHV0NEc1MmlHS1BaIiwiSWQiOiJ0bE5laFBMQS9OTHJiK3RmMzhhNzBHS0R6MDV0d1FDNytWdFR1UjRSTkQxWGQ3VnlqUjYrdUtyMzdqd1d4NnRYY3pYTlZzYUNGaXVnMzFmcXFhQkozaDhmb2ZUTVRvSXpBeXk5b3I0QUVTVXJGRXA5SEJiR1FRTG9yVWFFNk5WUE8vZDZRMllLRU8vRkVpSFZJTXdmZHkxQlowVldWSVZxY1E9PSJ9"}}
[LOG] 0:00.521 DEBUG httpbakery client do POST https://127.0.0.1:36084/discharge {
[LOG] 0:00.521 DEBUG httpbakery dischargeHandler.serveDischarge {
[LOG] 0:00.521 INFO bakery server attempting to discharge "eyJUaGlyZFBhcnR5UHVibGljS2V5IjoieVo2OGdDMUd3SVZsMWJrM0h1Rk1Ld0hpNzZsTHZvUzBkU0w2Q0lhNnJ5ST0iLCJGaXJzdFBhcnR5UHVibGljS2V5IjoiZ3hxM2o1WS9LdGNXRWhZRG84WGdTUFdaTVFGNVl0cFV4blpMcSszcGQyST0iLCJOb25jZSI6IkRVMjdnRUdmYi9jRWR6d3VFUkZWOHV0NEc1MmlHS1BaIiwiSWQiOiJ0bE5laFBMQS9OTHJiK3RmMzhhNzBHS0R6MDV0d1FDNytWdFR1UjRSTkQxWGQ3VnlqUjYrdUtyMzdqd1d4NnRYY3pYTlZzYUNGaXVnMzFmcXFhQkozaDhmb2ZUTVRvSXpBeXk5b3I0QUVTVXJGRXA5SEJiR1FRTG9yVWFFNk5WUE8vZDZRMllLRU8vRkVpSFZJTXdmZHkxQlowVldWSVZxY1E9PSJ9"
[LOG] 0:00.522 DEBUG httpbakery }
[LOG] 0:00.522 DEBUG httpbakery serveDischarge -> &httpbakery.dischargeResponse{Macaroon:(*macaroon.Macaroon)(0xc420236850)}
[LOG] 0:00.522 DEBUG httpbakery } -> error <nil>
[LOG] 0:00.525 DEBUG juju.apiserver model login: user testuser@somewhere has "login" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.525 DEBUG juju.apiserver model login: user-testuser@somewhere for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.528 DEBUG juju.charm charm is not in revision control directory
[LOG] 0:00.529 DEBUG httpbakery client do POST https://localhost:34947/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms?revision=1&schema=local&series=quantal {
[LOG] 0:00.543 DEBUG juju.apiserver.httpcontext sending error: 401 verification failed: macaroon not found in storage
[LOG] 0:00.544 DEBUG httpbakery postFormJSON to https://127.0.0.1:36084/discharge; vals: url.Values{"id":[]string{"eyJUaGlyZFBhcnR5UHVibGljS2V5IjoieVo2OGdDMUd3SVZsMWJrM0h1Rk1Ld0hpNzZsTHZvUzBkU0w2Q0lhNnJ5ST0iLCJGaXJzdFBhcnR5UHVibGljS2V5IjoiZ3hxM2o1WS9LdGNXRWhZRG84WGdTUFdaTVFGNVl0cFV4blpMcSszcGQyST0iLCJOb25jZSI6ImtEK1paS3graVg3TW5hN3RzMkRsT0lFRTBGd1lQOEIwIiwiSWQiOiJHODA0OFhoQzZaYWVRMXBRTUhIdEdNUUlaTkc2WndnMGtIL0lMVm9UQitBMzY4SFJQajc3SmpsY0w3QTdjV1hMUURCdWdpV0YxU3dsU2NuSzFPeWpUb05ZYzFnNkhTbm5xaWNwMkFGekFEdkNUTW9VRFBhT0pnYm4xaTlOaFVlMlhrWUhKY2xPV0dOVmRESVhCVUVSODZlRHJCV3hNaVdpN3c9PSJ9"}}
[LOG] 0:00.544 DEBUG httpbakery client do POST https://127.0.0.1:36084/discharge {
[LOG] 0:00.544 DEBUG httpbakery dischargeHandler.serveDischarge {
[LOG] 0:00.544 INFO bakery server attempting to discharge "eyJUaGlyZFBhcnR5UHVibGljS2V5IjoieVo2OGdDMUd3SVZsMWJrM0h1Rk1Ld0hpNzZsTHZvUzBkU0w2Q0lhNnJ5ST0iLCJGaXJzdFBhcnR5UHVibGljS2V5IjoiZ3hxM2o1WS9LdGNXRWhZRG84WGdTUFdaTVFGNVl0cFV4blpMcSszcGQyST0iLCJOb25jZSI6ImtEK1paS3graVg3TW5hN3RzMkRsT0lFRTBGd1lQOEIwIiwiSWQiOiJHODA0OFhoQzZaYWVRMXBRTUhIdEdNUUlaTkc2WndnMGtIL0lMVm9UQitBMzY4SFJQajc3SmpsY0w3QTdjV1hMUURCdWdpV0YxU3dsU2NuSzFPeWpUb05ZYzFnNkhTbm5xaWNwMkFGekFEdkNUTW9VRFBhT0pnYm4xaTlOaFVlMlhrWUhKY2xPV0dOVmRESVhCVUVSODZlRHJCV3hNaVdpN3c9PSJ9"
[LOG] 0:00.544 DEBUG httpbakery }
[LOG] 0:00.544 DEBUG httpbakery serveDischarge -> &httpbakery.dischargeResponse{Macaroon:(*macaroon.Macaroon)(0xc42021c7e0)}
[LOG] 0:00.544 DEBUG httpbakery } -> error <nil>
[LOG] 0:00.556 ERROR juju.apiserver returning error from POST /model/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms?%3Amodeluuid=deadbeef-0bad-400d-8000-4b1d0d06f00d&revision=1&schema=local&series=quantal: [{github.com/juju/juju/apiserver/charms.go:70: } {github.com/juju/juju/apiserver/charms.go:62: cannot upload charm} {github.com/juju/juju/apiserver/charms.go:105: } {github.com/juju/juju/apiserver/charms.go:319: cannot open charm archive} {zip: not a valid zip file}]
[LOG] 0:00.556 DEBUG httpbakery } -> error <nil>
client_macaroon_test.go:68:
c.Assert(err, jc.ErrorIsNil)
... value *errors.Err = &errors.unformatter{message:"", cause:(*params.Error)(0xc420d0b320), previous:(*errors.Err)(0xc420b7eeb0), file:"github.com/juju/juju/api/client.go", line:350} ()
... error stack:
cannot upload charm: cannot open charm archive: zip: not a valid zip file
github.com/juju/juju/api/client.go:578:
github.com/juju/juju/api/client.go:396:
github.com/juju/juju/api/client.go:350:

[LOG] 0:00.557 DEBUG juju.api RPC connection died
[LOG] 0:00.557 DEBUG juju.api RPC connection died
[LOG] 0:00.558 DEBUG juju.state closed state without error
[LOG] 0:00.558 INFO juju.provider.dummy reset model
[LOG] 0:00.558 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:34947->127.0.0.1:51738: write: broken pipe
[LOG] 0:00.558 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:34947->127.0.0.1:51722: write: broken pipe
[LOG] 0:00.566 DEBUG juju.state closed state without error
[LOG] 0:00.570 INFO juju.testing reset successfully reset admin password
[LOG] 0:00.593 INFO juju.testing reset successfully reset admin password

----------------------------------------------------------------------

Tags:

Simon Richardson (simonrichardson) on 2018-08-22

Changed in juju:
status:	Triaged → Incomplete
importance:	High → Medium

Revision history for this message

Christian Muirhead (2-xtian) wrote on 2018-08-24:

I just saw this again: http://ci.jujucharms.com/job/github-merge-juju/985/testReport/

Christian Muirhead (2-xtian) on 2018-08-24

tags:

added: intermittent-failure

Anastasia (anastasia-macmood) on 2018-08-31

Changed in juju:
status:	Incomplete → In Progress
assignee:	nobody → Anastasia (anastasia-macmood)

Revision history for this message

Anastasia (anastasia-macmood) wrote on 2018-08-31:

trialing fix against develop: https://github.com/juju/juju/pull/9146

Anastasia (anastasia-macmood) on 2018-09-03

Changed in juju:
status:	In Progress → Fix Committed

Revision history for this message

Christian Muirhead (2-xtian) wrote on 2018-09-06:

Seen again: http://ci.jujucharms.com/job/github-merge-juju/1087/testReport/junit/github/com_juju_juju_api/TestAll/

Changed in juju:
status:	Fix Committed → Confirmed

Revision history for this message

Anastasia (anastasia-macmood) wrote on 2018-09-10:

Added local charm archive size check to ensure that we have a valid charm setup before we start the test.
PR against develop: https://github.com/juju/juju/pull/9175

Changed in juju:
status:	Confirmed → In Progress

Anastasia (anastasia-macmood) on 2018-09-10

Changed in juju:
status:	In Progress → Fix Committed

Revision history for this message

Anastasia (anastasia-macmood) wrote on 2018-09-17:

Still seems to be happening as per http://ci.jujucharms.com/job/github-merge-juju/1146/consoleFull

Changed in juju:
status:	Fix Committed → In Progress

Anastasia (anastasia-macmood) on 2018-09-18

Changed in juju:
status:	In Progress → Triaged
assignee:	Anastasia (anastasia-macmood) → nobody

Revision history for this message

Heather Lanigan (hmlanigan) wrote on 2018-10-23:

http://ci.jujucharms.com/job/make-check-juju/869/consoleFull

Richard Harding (rharding) on 2018-11-09

Changed in juju:
milestone:	2.5-beta1 → 2.5-beta2

Richard Harding (rharding) on 2018-11-28

Changed in juju:
milestone:	2.5-beta2 → 2.5.1

Ian Booth (wallyworld) on 2019-01-28

Changed in juju:
milestone:	2.5.1 → 2.5.2

Canonical Juju QA Bot (juju-qa-bot) on 2019-03-11

Changed in juju:
milestone:	2.5.2 → 2.5.3

Canonical Juju QA Bot (juju-qa-bot) on 2019-03-26

Changed in juju:
milestone:	2.5.3 → 2.5.4

Canonical Juju QA Bot (juju-qa-bot) on 2019-04-02

Changed in juju:
milestone:	2.5.4 → 2.5.5

Anastasia (anastasia-macmood) on 2019-05-14

Changed in juju:
milestone:	2.5.6 → 2.5.8

Canonical Juju QA Bot (juju-qa-bot) on 2019-06-28

Changed in juju:
milestone:	2.5.8 → 2.5.9

Revision history for this message

Anastasia (anastasia-macmood) wrote on 2019-10-31:

Removing from a milestone as this work will not be done in 2.5 series.

Changed in juju:
milestone:	2.5.9 → none

Revision history for this message

Canonical Juju QA Bot (juju-qa-bot) wrote on 2022-11-03:

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.

Changed in juju:
importance:	Medium → Low
tags:	added: expirebugs-bot

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.