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

Bug #1788401 reported by Simon Richardson on 2018-08-22
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
juju
Medium
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

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

Changed in juju:
status: Triaged → Incomplete
importance: High → Medium
tags: added: intermittent-failure
Changed in juju:
status: Incomplete → In Progress
assignee: nobody → Anastasia (anastasia-macmood)
Anastasia (anastasia-macmood) wrote :

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

Changed in juju:
status: In Progress → Fix Committed
Christian Muirhead (2-xtian) wrote :
Changed in juju:
status: Fix Committed → Confirmed
Anastasia (anastasia-macmood) wrote :

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
Changed in juju:
status: In Progress → Fix Committed
Anastasia (anastasia-macmood) wrote :
Changed in juju:
status: Fix Committed → In Progress
Changed in juju:
status: In Progress → Triaged
assignee: Anastasia (anastasia-macmood) → nobody
Changed in juju:
milestone: 2.5-beta1 → 2.5-beta2
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
Changed in juju:
milestone: 2.5.2 → 2.5.3
Changed in juju:
milestone: 2.5.3 → 2.5.4
Changed in juju:
milestone: 2.5.4 → 2.5.5
Changed in juju:
milestone: 2.5.6 → 2.5.8
Changed in juju:
milestone: 2.5.8 → 2.5.9
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers