cmd/jujud: sporadic failure

[Roger Peppe]

It has failed just once for me when running all juju tests - I cannot reproduce - but
the log is puzzling, so this is a record in case it happens again:

Note the API port number - it starts by listening and dialling 51273,
but then switches to 47573. How could that be happening?

FAIL: machine_test.go:426: MachineSuite.TestManageStateRunsMinUnitsWorker
47573
[LOG] 54.52973 INFO juju environs/testing: uploading FAKE tools 1.13.2-raring-amd64
[LOG] 54.52978 INFO juju environs/testing: uploading FAKE tools 1.13.2-precise-amd64
[LOG] 54.55040 INFO juju.environs.boostrap bootstrapping environment "dummyenv"
[LOG] 54.55043 INFO juju environs: reading tools with major version 1
[LOG] 54.55044 INFO juju environs: filtering tools by version: %!s(int=1)
[LOG] 54.55045 INFO juju environs: filtering tools by series: precise
[LOG] 54.55046 DEBUG juju.environs.tools reading v1.* tools
[LOG] 54.55047 INFO juju environs: falling back to public bucket
[LOG] 54.55049 DEBUG juju.environs.tools reading v1.* tools
[LOG] 54.55052 DEBUG juju.environs.tools found 1.13.2-precise-amd64
[LOG] 54.55056 DEBUG juju.environs.tools found 1.13.2-raring-amd64
[LOG] 54.55059 INFO juju environs/dummy: would pick tools from 1.13.2-precise-amd64
[LOG] 54.56815 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity ""
[LOG] 54.58879 INFO juju.state connection established
[LOG] 54.60593 INFO juju.state initializing environment
[LOG] 54.62943 INFO juju state/api: listening on "127.0.0.1:51273"
[LOG] 54.64959 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity ""
[LOG] 54.65567 INFO juju.state connection established
[LOG] 54.67448 INFO juju juju: authorization error while connecting to state server; retrying
[LOG] 54.67452 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity ""
[LOG] 54.67748 INFO juju.state connection established
[LOG] 54.70758 INFO juju state/api: dialing "wss://127.0.0.1:51273/"
[LOG] 54.71053 INFO juju state/api: connection established
[LOG] 54.71063 DEBUG juju rpc/jsoncodec: <- {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"user-admin","Password":"dummy-secret","Nonce":""}}
[LOG] 54.71100 DEBUG juju rpc/jsoncodec: -> {"RequestId":1,"Response":{}}
[LOG] 54.71129 DEBUG juju rpc/jsoncodec: <- {"RequestId":2,"Type":"Pinger","Request":"Ping","Params":{}}
[LOG] 54.71135 DEBUG juju rpc/jsoncodec: -> {"RequestId":2,"Response":{}}
[LOG] 54.71149 INFO juju.container.lxc lxcObjectFactory replaced with mock lxc factory
[LOG] 54.75967 INFO juju machine agent machine-0 start
[LOG] 54.77956 INFO juju Starting StateWorker for machine-0
[LOG] 54.77966 INFO juju worker: start "state"
[LOG] 54.77968 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity "machine-0"
[LOG] 54.77991 INFO juju worker: start "api"
[LOG] 54.78012 INFO juju state/api: dialing "wss://localhost:47573/"
[LOG] 54.78048 ERROR juju state/api: websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 54.78051 ERROR juju worker: exited "api": websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 54.78053 INFO juju worker: restarting "api" in 3s
[LOG] 54.80140 INFO juju.state connection established
[LOG] 54.80922 INFO juju worker: start "lxc-provisioner"
[LOG] 54.80926 INFO juju worker: start "apiserver"
[LOG] 54.80931 INFO juju worker: start "cleaner"
[LOG] 54.80934 ERROR juju worker: fatal "apiserver": listen tcp <nil>:47573: address already in use
[LOG] 54.80935 DEBUG juju worker: killing "lxc-provisioner"
[LOG] 54.80937 DEBUG juju worker: killing "cleaner"
[LOG] 54.80938 INFO juju worker: ignoring start request for "resumer" when dying
[LOG] 54.80946 INFO juju worker: ignoring start request for "minunitsworker" when dying
[LOG] 54.81427 INFO juju writing charm to storage [853 bytes]
[LOG] 54.81431 INFO juju adding charm to state
[LOG] 54.81525 ERROR juju worker: exited "state": listen tcp <nil>:47573: address already in use
[LOG] 54.81526 INFO juju worker: restarting "state" in 3s
[LOG] 57.78064 INFO juju worker: start "api"
[LOG] 57.78091 INFO juju state/api: dialing "wss://localhost:47573/"
[LOG] 57.78108 ERROR juju state/api: websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 57.78111 ERROR juju worker: exited "api": websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 57.78113 INFO juju worker: restarting "api" in 3s
[LOG] 57.81536 INFO juju worker: start "state"
[LOG] 57.81539 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity "machine-0"
[LOG] 57.81744 INFO juju.state connection established
[LOG] 57.81930 INFO juju worker: start "lxc-provisioner"
[LOG] 57.81932 INFO juju worker: start "apiserver"
[LOG] 57.81937 INFO juju worker: start "cleaner"
[LOG] 57.81939 ERROR juju worker: fatal "apiserver": listen tcp <nil>:47573: address already in use
[LOG] 57.81940 DEBUG juju worker: killing "lxc-provisioner"
[LOG] 57.81941 DEBUG juju worker: killing "cleaner"
[LOG] 57.81941 INFO juju worker: ignoring start request for "resumer" when dying
[LOG] 57.81950 INFO juju worker: ignoring start request for "minunitsworker" when dying
[LOG] 57.81969 ERROR juju worker: exited "state": listen tcp <nil>:47573: address already in use
[LOG] 57.81970 INFO juju worker: restarting "state" in 3s
[LOG] 60.78125 INFO juju worker: start "api"
[LOG] 60.78152 INFO juju state/api: dialing "wss://localhost:47573/"
[LOG] 60.78168 ERROR juju state/api: websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 60.78171 ERROR juju worker: exited "api": websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 60.78172 INFO juju worker: restarting "api" in 3s
[LOG] 60.81982 INFO juju worker: start "state"
[LOG] 60.81985 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity "machine-0"
[LOG] 60.82836 INFO juju.state connection established
[LOG] 60.83192 INFO juju worker: start "lxc-provisioner"
[LOG] 60.83195 INFO juju worker: start "apiserver"
[LOG] 60.83201 INFO juju worker: start "cleaner"
[LOG] 60.83203 ERROR juju worker: fatal "apiserver": listen tcp <nil>:47573: address already in use
[LOG] 60.83204 DEBUG juju worker: killing "lxc-provisioner"
[LOG] 60.83206 DEBUG juju worker: killing "cleaner"
[LOG] 60.83207 INFO juju worker: ignoring start request for "resumer" when dying
[LOG] 60.83213 INFO juju worker: ignoring start request for "minunitsworker" when dying
[LOG] 60.83245 ERROR juju worker: exited "state": listen tcp <nil>:47573: address already in use
[LOG] 60.83246 INFO juju worker: restarting "state" in 3s
[LOG] 63.78186 INFO juju worker: start "api"
[LOG] 63.78209 INFO juju state/api: dialing "wss://localhost:47573/"
[LOG] 63.78232 ERROR juju state/api: websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 63.78235 ERROR juju worker: exited "api": websocket.Dial wss://localhost:47573/: dial tcp 127.0.0.1:47573: connection refused
[LOG] 63.78236 INFO juju worker: restarting "api" in 3s
[LOG] 63.83259 INFO juju worker: start "state"
[LOG] 63.83262 INFO juju.state opening state; mongo addresses: ["localhost:57733"]; entity "machine-0"
[LOG] 63.83464 INFO juju.state connection established
[LOG] 63.83913 INFO juju worker: start "lxc-provisioner"
[LOG] 63.83916 INFO juju worker: start "apiserver"
[LOG] 63.83922 INFO juju worker: start "cleaner"
[LOG] 63.83924 ERROR juju worker: fatal "apiserver": listen tcp <nil>:47573: address already in use
[LOG] 63.83926 DEBUG juju worker: killing "lxc-provisioner"
[LOG] 63.83927 DEBUG juju worker: killing "cleaner"
[LOG] 63.83928 INFO juju worker: ignoring start request for "resumer" when dying
[LOG] 63.83940 INFO juju worker: ignoring start request for "minunitsworker" when dying
[LOG] 63.83979 ERROR juju worker: exited "state": listen tcp <nil>:47573: address already in use
[LOG] 63.83981 INFO juju worker: restarting "state" in 3s
machine_test.go:456:
    s.assertJobWithState(c, state.JobManageState, func(conf agent.Config, agentState *state.State) {
        // Ensure that the MinUnits worker is alive by doing a simple check
        // that it responds to state changes: add a service, set its minimum
        // number of units to one, wait for the worker to add the missing unit.
        service, err := s.State.AddService("wordpress", s.AddTestingCharm(c, "wordpress"))
        c.Assert(err, gc.IsNil)
        err = service.SetMinUnits(1)
        c.Assert(err, gc.IsNil)
        w := service.Watch()
        defer w.Stop()

        // Trigger a sync on the state used by the agent, and wait for the unit
        // to be created.
        agentState.StartSync()
        timeout := time.After(testing.LongWait)
        for {
            select {
            case <-timeout:
                c.Fatalf("unit not created")
            case <-time.After(testing.ShortWait):
                s.State.StartSync()
            case <-w.Changes():
                units, err := service.AllUnits()
                c.Assert(err, gc.IsNil)
                if len(units) == 1 {
                    return
                }
            }
        }
    })
machine_test.go:445:
    c.Fatalf("unit not created")
... Error: unit not created

[LOG] 64.83699 DEBUG juju worker: killing runner 0xc2004ad780
[LOG] 64.83707 ERROR juju worker: exited "api": unexpected quit
[LOG] 64.83711 INFO juju worker: runner is dying
[LOG] 64.83715 DEBUG juju worker: killing "state"
[LOG] 64.83720 DEBUG juju worker: killing runner 0xc200572ea0
[LOG] 64.83726 INFO juju worker: restarting "api" in 3s
[LOG] 64.83741 INFO juju.container.lxc lxcObjectFactory replaced with &{}
[LOG] 64.83817 INFO juju environs/dummy: reset environment
[LOG] 64.83829 DEBUG juju rpc/jsoncodec: <- error: read tcp 127.0.0.1:58755: use of closed network connection (closing true)
[jujuc whatever]
[remote]
[/path/to/remote]
[remote --help]
[unknown]
[remote --error borken]
[remote --unknown]
[remote unwanted]
OOPS: 31 passed, 3 skipped, 1 FAILED
--- FAIL: TestPackage (58.54 seconds)
FAIL
FAIL launchpad.net/juju-core/cmd/jujud 58.778s

[Ian Booth (wallyworld)]

This is now really old and I can't recall seeing it reappear so marking as Incomplete. We can reopen if required.

[Launchpad Janitor (janitor)]

[Expired for juju-core because there has been no activity for 60 days.]