uniter sporadic test failure

[Roger Peppe]

Here's the log output. I've only seen this failure once so far.

test 25: upgrade conflict resolved with forced upgrade

step 0
uniter_test.startUpgradeError{}
uniter_test.createCharm{revision:0, badHooks:[]string(nil), customize:(func(*gocheck.C, string))(0x437a20)}
uniter_test.serveCharm{}
uniter_test.createUniter{}
uniter_test.createServiceAndUnit{}
uniter_test.startUniter{}
[LOG] 87.04142 JUJU unit "u/0" started
[LOG] 87.05939 JUJU:DEBUG presence: starting pinger for "u#u/0" with seq=1
[LOG] 87.05941 JUJU:DEBUG presence: pinging "u#u/0" with seq=1
[LOG] 87.05979 JUJU:DEBUG filter: no new charm event
[LOG] 87.06079 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"units", id:"u/0"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf8409eb8a0), revno:2}}
[LOG] 87.06121 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"services", id:"u"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf840974d20), revno:3}}
[LOG] 87.06136 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"settings", id:"s#u"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf8409ca660), revno:0}}
[LOG] 87.06141 JUJU:DEBUG filter: got unit change
[LOG] 87.06144 JUJU:DEBUG filter: got service change
[LOG] 87.06147 JUJU:DEBUG filter: no new charm event
[LOG] 87.06191 JUJU ModeInit starting
[LOG] 87.06193 JUJU updating unit addresses
[LOG] 87.07536 JUJU:DEBUG ModeInit exiting
[LOG] 87.07539 JUJU ModeContinue starting
[LOG] 87.07547 JUJU charm is not deployed
[LOG] 87.07608 JUJU:DEBUG ModeContinue exiting
[LOG] 87.07610 JUJU ModeInstalling cs:series/dummy-0 starting
[LOG] 87.07619 JUJU fetching charm "cs:series/dummy-0"
[LOG] 87.07644 JUJU downloading cs:series/dummy-0 from http://localhost:59717/charms/0
[LOG] 87.07739 JUJU download complete
[LOG] 87.07756 JUJU download verified
uniter_test.waitUnit{status:"started", info:"", charm:0, resolved:""}
[LOG] 87.09110 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.09116 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.09125 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.09152 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.09219 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc8"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.09255 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc7"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.09291 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc6"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{2}}}}, bson.DocElem{Name:"services", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.09316 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc5"}, bson.DocElem{Name:"services", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u"}}, bson.DocElem{Name:"r", Value:[]interface {}{2}}}}}
[LOG] 87.09337 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc4"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"e"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.09361 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc3"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"e"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.09385 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc2"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"e"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.09409 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc1"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"e"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.09485 JUJU:DEBUG filter: got unit change
[LOG] 87.09502 JUJU:DEBUG presence: found seq=1 alive with key "u#u/0"
[LOG] 87.12315 JUJU deploying charm "cs:series/dummy-0"
[LOG] 87.13014 JUJU preparing new charm deployment
want unit charm "cs:series/dummy-0", got ""; still waiting
[LOG] 87.14277 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.14286 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.14301 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.14322 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
want unit charm "cs:series/dummy-0", got ""; still waiting
[LOG] 87.19403 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.19409 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.19415 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.19433 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
want unit charm "cs:series/dummy-0", got ""; still waiting
[LOG] 87.24554 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.24562 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.24571 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.24596 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.25961 JUJU deploying charm
[LOG] 87.26312 JUJU charm deployment succeeded
[LOG] 87.27131 JUJU charm "cs:series/dummy-0" is deployed
[LOG] 87.28389 JUJU:DEBUG ModeInstalling cs:series/dummy-0 exiting
[LOG] 87.28393 JUJU ModeContinue starting
[LOG] 87.28418 JUJU found queued "install" hook
[LOG] 87.28924 JUJU running "install" hook
want unit status "started", got "pending"; still waiting
[LOG] 87.29845 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.29852 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.29860 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.29875 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.29979 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xc9"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{5}}}}}
[LOG] 87.30082 JUJU:DEBUG filter: got unit change
[LOG] 87.32253 JUJU u/0: UniterSuite-25 install
[LOG] 87.32859 JUJU ran "install" hook
[LOG] 87.32865 JUJU committing "install" hook
want unit status "started", got "pending"; still waiting
[LOG] 87.35097 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.35104 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.35112 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.35126 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.36328 JUJU committed "install" hook
[LOG] 87.36364 JUJU:DEBUG ModeContinue exiting
[LOG] 87.36365 JUJU ModeContinue starting
[LOG] 87.36381 JUJU continuing after "install" hook
[LOG] 87.36381 JUJU:DEBUG ModeContinue exiting
[LOG] 87.36382 JUJU ModeStarting starting
[LOG] 87.38337 JUJU running "start" hook
[LOG] 87.40175 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf84026fba0)}
want unit status "started", got "installed"; still waiting
[LOG] 87.40178 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.40180 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.40182 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.40186 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.40206 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xcb"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{2}}}}}
[LOG] 87.40217 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xca"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{-1}}}}}
[LOG] 87.40923 JUJU u/0: UniterSuite-25 start
[LOG] 87.41654 JUJU ran "start" hook
[LOG] 87.41660 JUJU committing "start" hook
[LOG] 87.45475 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf8409fdde0)}
want unit status "started", got "installed"; still waiting
[LOG] 87.45498 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.45502 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.45505 JUJU committed "start" hook
[LOG] 87.45529 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.45544 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.45578 JUJU:DEBUG ModeStarting exiting
[LOG] 87.45583 JUJU ModeContinue starting
[LOG] 87.45721 JUJU continuing after "start" hook
[LOG] 87.45725 JUJU:DEBUG ModeContinue exiting
[LOG] 87.45726 JUJU ModeAbide starting
[LOG] 87.46916 JUJU:DEBUG filter: want config event
[LOG] 87.46919 JUJU:DEBUG filter: sent config event
[LOG] 87.47463 JUJU running "config-changed" hook
[LOG] 87.50652 JUJU u/0: UniterSuite-25 config-changed
[LOG] 87.50803 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf84026fba0)}
uniter_test.waitHooks{"install", "start", "config-changed"}
waiting for hooks: []string{"install", "start", "config-changed"}
actual: []string{"install", "start", "config-changed"}
uniter_test.verifyCharm{revision:0, dirty:false}
[LOG] 87.65154 JUJU ran "config-changed" hook
[LOG] 87.65160 JUJU committing "config-changed" hook
[LOG] 87.67597 JUJU committed "config-changed" hook
[LOG] 87.67665 JUJU:DEBUG filter: want upgrade event
[LOG] 87.67668 JUJU:DEBUG filter: no new charm event
uniter_test.createCharm{revision:1, badHooks:[]string(nil), customize:(func(*gocheck.C, string))(0x437c60)}
uniter_test.serveCharm{}
uniter_test.upgradeCharm{revision:1, forced:false}
uniter_test.waitUnit{status:"error", info:"upgrade failed", charm:0, resolved:""}
[LOG] 87.74476 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.74478 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.74481 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.74488 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.74540 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xce"}, bson.DocElem{Name:"services", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.74555 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xcd"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.74566 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtApon\xa5h\xf9\x00\x02\xcc"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{3}}}}}
[LOG] 87.74607 JUJU:DEBUG filter: got service change
[LOG] 87.74608 JUJU:DEBUG filter: preparing new upgrade event
[LOG] 87.74654 JUJU:DEBUG filter: sent upgrade event
[LOG] 87.74658 JUJU:DEBUG ModeAbide exiting
[LOG] 87.74658 JUJU ModeUpgrading cs:series/dummy-1 starting
[LOG] 87.74678 JUJU fetching charm "cs:series/dummy-1"
[LOG] 87.74688 JUJU downloading cs:series/dummy-1 from http://localhost:59717/charms/1
[LOG] 87.74770 JUJU download complete
[LOG] 87.74788 JUJU download verified
[LOG] 87.79740 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf8406c8ea0)}
want unit status "error", got "started"; still waiting
[LOG] 87.79753 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.79756 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.79767 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.79795 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.82947 JUJU deploying charm "cs:series/dummy-1"
[LOG] 87.83700 JUJU preparing charm upgrade
[LOG] 87.84446 JUJU deploying charm
[LOG] 87.84940 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf8409ca1e0)}
want unit status "error", got "started"; still waiting
[LOG] 87.84953 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.84957 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.84968 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.84992 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.88977 JUJU git command failed: exit status 1
path: /tmp/gocheck-2775422040480279449/0/agents/unit-u-0/charm
args: []string{"pull", "/tmp/gocheck-2775422040480279449/0/agents/unit-u-0/state/deployer/current"}
From /tmp/gocheck-2775422040480279449/0/agents/unit-u-0/state/deployer/current
 * branch HEAD -> FETCH_HEAD
Auto-merging data
CONFLICT (add/add): Merge conflict in data
Automatic merge failed; fix conflicts and then commit the result.

[LOG] 87.89482 JUJU charm deployment completed with conflicts
[LOG] 87.89490 JUJU:DEBUG ModeUpgrading cs:series/dummy-1 exiting
[LOG] 87.89492 JUJU ModeConflicted starting
uniter_test.verifyWaiting{}
uniter_test.stopUniter{err:""}
[LOG] 87.90782 JUJU:DEBUG filter: want resolved event
[LOG] 87.90785 JUJU:DEBUG filter: want upgrade event
[LOG] 87.90787 JUJU:DEBUG filter: no new charm event
[LOG] 87.90790 JUJU:DEBUG ModeConflicted exiting
[LOG] 87.90793 JUJU unit "u/0" shutting down: tomb: dying
[LOG] 87.90795 JUJU:DEBUG presence: stopping pinger for "u#u/0" with seq=1
[LOG] 87.90807 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"settings", id:"s#u"}, ch:(chan<- watcher.Change)(0xf8409ca660)}
[LOG] 87.90814 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"services", id:"u"}, ch:(chan<- watcher.Change)(0xf840974d20)}
[LOG] 87.90820 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"units", id:"u/0"}, ch:(chan<- watcher.Change)(0xf8409eb8a0)}
[LOG] 87.90822 JUJU filter error: tomb: dying
uniter_test.startUniter{}
uniter_test.waitHooks{}
[LOG] 87.90841 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 87.90848 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 87.90855 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 87.90871 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 87.90974 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd0"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.91007 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xcf"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{4}}}}}
[LOG] 87.91132 JUJU unit "u/0" started
[LOG] 87.91264 JUJU:DEBUG presence: starting pinger for "u#u/0" with seq=2
[LOG] 87.91267 JUJU:DEBUG presence: pinging "u#u/0" with seq=2
[LOG] 87.91302 JUJU:DEBUG filter: no new charm event
[LOG] 87.91403 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"units", id:"u/0"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf8409caae0), revno:5}}
[LOG] 87.91427 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"services", id:"u"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf840974360), revno:4}}
[LOG] 87.91439 JUJU:DEBUG watcher: got request: watcher.reqWatch{key:watcher.watchKey{c:"settings", id:"s#u"}, info:watcher.watchInfo{ch:(chan<- watcher.Change)(0xf840296ae0), revno:0}}
[LOG] 87.91447 JUJU:DEBUG filter: got service change
[LOG] 87.91448 JUJU:DEBUG filter: no new charm event
[LOG] 87.91450 JUJU:DEBUG filter: got unit change
[LOG] 87.91461 JUJU ModeInit starting
[LOG] 87.91462 JUJU updating unit addresses
[LOG] 87.92662 JUJU:DEBUG ModeInit exiting
[LOG] 87.92665 JUJU ModeContinue starting
[LOG] 87.92767 JUJU resuming charm upgrade
[LOG] 87.92772 JUJU:DEBUG ModeContinue exiting
[LOG] 87.92773 JUJU ModeUpgrading cs:series/dummy-1 starting
[LOG] 87.92803 JUJU fetching charm "cs:series/dummy-1"
[LOG] 87.93521 JUJU deploying charm "cs:series/dummy-1"
[LOG] 87.94237 JUJU preparing charm upgrade
[LOG] 87.96080 JUJU deploying charm
[LOG] 87.98776 JUJU git command failed: exit status 1
path: /tmp/gocheck-2775422040480279449/0/agents/unit-u-0/charm
args: []string{"pull", "/tmp/gocheck-2775422040480279449/0/agents/unit-u-0/state/deployer/current"}
M .juju-charm
U data
M hooks/start
A ignore
M revision
Pull is not possible because you have unmerged files.
Please, fix them up in the work tree, and then use 'git add/rm <file>'
as appropriate to mark resolution, or use 'git commit -a'.

[LOG] 87.99305 JUJU charm deployment completed with conflicts
[LOG] 87.99311 JUJU:DEBUG ModeUpgrading cs:series/dummy-1 exiting
[LOG] 87.99314 JUJU ModeConflicted starting
[LOG] 88.00059 JUJU:DEBUG filter: want resolved event
[LOG] 88.00060 JUJU:DEBUG filter: want upgrade event
[LOG] 88.00061 JUJU:DEBUG filter: no new charm event
waiting for hooks: []string{"install", "start", "config-changed"}
actual: []string{"install", "start", "config-changed"}
uniter_test.verifyCharm{revision:0, dirty:true}
step 1
uniter_test.createCharm{revision:2, badHooks:[]string(nil), customize:(func(*gocheck.C, string))(0x436e70)}
step 2
uniter_test.serveCharm{}
step 3
uniter_test.upgradeCharm{revision:2, forced:true}
step 4
uniter_test.waitUnit{status:"started", info:"", charm:2, resolved:""}
[LOG] 88.25008 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.25013 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.25022 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.25037 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.25090 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd5"}, bson.DocElem{Name:"services", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u"}}, bson.DocElem{Name:"r", Value:[]interface {}{5}}}}}
[LOG] 88.25109 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd4"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{5}}}}}
[LOG] 88.25127 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd3"}, bson.DocElem{Name:"settings", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u#u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{5}}}}}
[LOG] 88.25143 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd2"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{7}}}}}
[LOG] 88.25159 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd1"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{6}}}}}
[LOG] 88.25228 JUJU:DEBUG filter: got unit change
[LOG] 88.25247 JUJU:DEBUG filter: got service change
[LOG] 88.25248 JUJU:DEBUG filter: preparing new upgrade event
[LOG] 88.25298 JUJU:DEBUG filter: sent upgrade event
[LOG] 88.26681 JUJU:DEBUG ModeConflicted exiting
[LOG] 88.26685 JUJU ModeUpgrading cs:series/dummy-2 starting
[LOG] 88.26725 JUJU fetching charm "cs:series/dummy-2"
[LOG] 88.26736 JUJU downloading cs:series/dummy-2 from http://localhost:59717/charms/2
[LOG] 88.26860 JUJU download complete
[LOG] 88.26880 JUJU download verified
want unit charm "cs:series/dummy-2", got "cs:series/dummy-0"; still waiting
[LOG] 88.30235 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.30240 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.30248 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.30270 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.35062 JUJU deploying charm "cs:series/dummy-2"
want unit charm "cs:series/dummy-2", got "cs:series/dummy-0"; still waiting
[LOG] 88.35436 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.35441 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.35448 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.35468 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.35721 JUJU preparing charm upgrade
[LOG] 88.37119 JUJU deploying charm
want unit charm "cs:series/dummy-2", got "cs:series/dummy-0"; still waiting
[LOG] 88.40668 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.40672 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.40679 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.40696 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
want unit charm "cs:series/dummy-2", got "cs:series/dummy-0"; still waiting
[LOG] 88.45902 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.45908 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.45914 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.45927 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.49488 JUJU charm deployment succeeded
[LOG] 88.50215 JUJU charm "cs:series/dummy-2" is deployed
want unit status "started", got "error"; still waiting
[LOG] 88.51169 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.51175 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.51182 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.51196 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.51253 JUJU:DEBUG watcher: got changelog document: bson.D{bson.DocElem{Name:"_id", Value:"PtAqon\xa5h\xf9\x00\x02\xd6"}, bson.DocElem{Name:"units", Value:bson.D{bson.DocElem{Name:"d", Value:[]interface {}{"u/0"}}, bson.DocElem{Name:"r", Value:[]interface {}{8}}}}}
[LOG] 88.51357 JUJU:DEBUG filter: got unit change
[LOG] 88.51574 JUJU:DEBUG ModeUpgrading cs:series/dummy-2 exiting
[LOG] 88.51578 JUJU ModeContinue starting
[LOG] 88.51604 JUJU found queued "upgrade-charm" hook
[LOG] 88.52127 JUJU running "upgrade-charm" hook
[LOG] 88.54946 JUJU u/0: UniterSuite-25 upgrade-charm
[LOG] 88.55592 JUJU ran "upgrade-charm" hook
[LOG] 88.55598 JUJU committing "upgrade-charm" hook
want unit status "started", got "error"; still waiting
[LOG] 88.56901 JUJU:DEBUG watcher: got request: watcher.reqSync{done:(chan bool)(nil)}
[LOG] 88.56906 JUJU:DEBUG presence: got request: presence.reqSync{done:(chan bool)(nil)}
[LOG] 88.56920 JUJU:DEBUG watcher: loading new events from changelog collection...
[LOG] 88.56932 JUJU:DEBUG presence: synchronizing watcher knowledge with database...
[LOG] 88.60054 JUJU committed "upgrade-charm" hook
[LOG] 88.60081 JUJU:DEBUG ModeContinue exiting
[LOG] 88.60088 JUJU ModeContinue starting
[LOG] 88.60127 JUJU continuing after "upgrade-charm" hook
[LOG] 88.60130 JUJU:DEBUG ModeContinue exiting
[LOG] 88.60131 JUJU ModeAbide starting
[LOG] 88.61437 JUJU:DEBUG filter: want config event
[LOG] 88.61440 JUJU:DEBUG filter: sent config event
[LOG] 88.62002 JUJU running "config-changed" hook
[LOG] 88.62369 JUJU:DEBUG presence: got request: presence.reqAlive{key:"u#u/0", result:(chan bool)(0xf8409fd720)}
step 5
uniter_test.verifyCharm{revision:2, dirty:false}
[LOG] 88.65618 JUJU u/0: UniterSuite-25 config-changed
[LOG] 88.66395 JUJU ran "config-changed" hook
[LOG] 88.66401 JUJU committing "config-changed" hook
[LOG] 88.68440 JUJU git command failed: exit status 128
path: /tmp/gocheck-2775422040480279449/0/agents/unit-u-0/charm
args: []string{"commit", "--allow-empty", "-m", "Completed \"config-changed\" hook."}
fatal: Unable to create '/tmp/gocheck-2775422040480279449/0/agents/unit-u-0/charm/.git/index.lock': File exists.

If no other git process is currently running, this probably means a
git process crashed in this repository earlier. Make sure no other git
process is running and remove the file manually to continue.

[LOG] 88.68467 JUJU:DEBUG ModeAbide exiting
[LOG] 88.68474 JUJU unit "u/0" shutting down: ModeAbide: git commit failed: exit status 128
[LOG] 88.68476 JUJU:DEBUG presence: stopping pinger for "u#u/0" with seq=2
[LOG] 88.68495 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"settings", id:"s#u"}, ch:(chan<- watcher.Change)(0xf840296ae0)}
[LOG] 88.68505 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"services", id:"u"}, ch:(chan<- watcher.Change)(0xf840974360)}
[LOG] 88.68512 JUJU:DEBUG watcher: got request: watcher.reqUnwatch{key:watcher.watchKey{c:"units", id:"u/0"}, ch:(chan<- watcher.Change)(0xf8409caae0)}
[LOG] 88.68515 JUJU filter error: tomb: dying
step 6
uniter_test.custom{f:(func(*gocheck.C, *uniter_test.context))(0x437020)}
uniter_test.go:601:
    ctx.run(c, t.steps)
uniter_test.go:106:
    c.Assert(err, IsNil)
... value *errors.errorString = &errors.errorString{s:"ModeAbide: git commit failed: exit status 128"} ("ModeAbide: git commit failed: exit status 128")

[LOG] 88.70771 JUJU dummy: reset environment

[William Reade (fwereade)]

Ha. I wrote the tests so that a working uniter couldn't interfere with the tests, but neglected to prevent the tests from interfering with the uniter :/.