Yan Xu created MESOS-1782:
-----------------------------
Summary: AllocatorTest/0.FrameworkExited is flaky
Key: MESOS-1782
URL: https://issues.apache.org/jira/browse/MESOS-1782
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.20.0
Environment: ubuntu-12.04-gcc Jenkins VM
Reporter: Yan Xu
{noformat:title=}
[ RUN ] AllocatorTest/0.FrameworkExited
Using temporary directory '/tmp/AllocatorTest_0_FrameworkExited_B6WZng'
I0909 08:02:35.116555 18112 leveldb.cpp:176] Opened db in 31.64686ms
I0909 08:02:35.126065 18112 leveldb.cpp:183] Compacted db in 9.449823ms
I0909 08:02:35.126118 18112 leveldb.cpp:198] Created db iterator in 5858ns
I0909 08:02:35.126137 18112 leveldb.cpp:204] Seeked to beginning of db in 1136ns
I0909 08:02:35.126150 18112 leveldb.cpp:273] Iterated through 0 keys in the db
in 560ns
I0909 08:02:35.126178 18112 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0909 08:02:35.126502 18133 recover.cpp:425] Starting replica recovery
I0909 08:02:35.126601 18133 recover.cpp:451] Replica is in EMPTY status
I0909 08:02:35.127012 18133 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0909 08:02:35.127094 18133 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0909 08:02:35.127223 18133 recover.cpp:542] Updating replica status to STARTING
I0909 08:02:35.226631 18133 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 99.308134ms
I0909 08:02:35.226690 18133 replica.cpp:320] Persisted replica status to
STARTING
I0909 08:02:35.226812 18131 recover.cpp:451] Replica is in STARTING status
I0909 08:02:35.227246 18131 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0909 08:02:35.227308 18131 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0909 08:02:35.227409 18131 recover.cpp:542] Updating replica status to VOTING
I0909 08:02:35.228540 18129 master.cpp:286] Master
20140909-080235-16842879-44005-18112 (precise) started on 127.0.1.1:44005
I0909 08:02:35.228593 18129 master.cpp:332] Master only allowing authenticated
frameworks to register
I0909 08:02:35.228607 18129 master.cpp:337] Master only allowing authenticated
slaves to register
I0909 08:02:35.228620 18129 credentials.hpp:36] Loading credentials for
authentication from '/tmp/AllocatorTest_0_FrameworkExited_B6WZng/credentials'
I0909 08:02:35.228754 18129 master.cpp:366] Authorization enabled
I0909 08:02:35.229560 18129 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0909 08:02:35.229933 18129 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master : [email protected]:44005
I0909 08:02:35.230057 18127 master.cpp:1212] The newly elected leader is
[email protected]:44005 with id 20140909-080235-16842879-44005-18112
I0909 08:02:35.230129 18127 master.cpp:1225] Elected as the leading master!
I0909 08:02:35.230144 18127 master.cpp:1043] Recovering from registrar
I0909 08:02:35.230257 18127 registrar.cpp:313] Recovering registrar
I0909 08:02:35.232461 18131 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 4.999384ms
I0909 08:02:35.232489 18131 replica.cpp:320] Persisted replica status to VOTING
I0909 08:02:35.232544 18131 recover.cpp:556] Successfully joined the Paxos group
I0909 08:02:35.232611 18131 recover.cpp:440] Recover process terminated
I0909 08:02:35.232727 18131 log.cpp:656] Attempting to start the writer
I0909 08:02:35.233012 18131 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0909 08:02:35.238785 18131 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 5.749504ms
I0909 08:02:35.238818 18131 replica.cpp:342] Persisted promised to 1
I0909 08:02:35.244056 18131 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0909 08:02:35.244580 18131 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0909 08:02:35.250143 18131 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 5.382351ms
I0909 08:02:35.250319 18131 replica.cpp:676] Persisted action at 0
I0909 08:02:35.250901 18131 replica.cpp:508] Replica received write request for
position 0
I0909 08:02:35.251137 18131 leveldb.cpp:438] Reading position from leveldb took
18689ns
I0909 08:02:35.256597 18131 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 5.274169ms
I0909 08:02:35.256764 18131 replica.cpp:676] Persisted action at 0
I0909 08:02:35.263712 18126 replica.cpp:655] Replica received learned notice
for position 0
I0909 08:02:35.269613 18126 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 5.417225ms
I0909 08:02:35.351641 18126 replica.cpp:676] Persisted action at 0
I0909 08:02:35.351655 18126 replica.cpp:661] Replica learned NOP action at
position 0
I0909 08:02:35.351889 18126 log.cpp:672] Writer started with ending position 0
I0909 08:02:35.352165 18126 leveldb.cpp:438] Reading position from leveldb took
25215ns
I0909 08:02:35.353163 18126 registrar.cpp:346] Successfully fetched the
registry (0B)
I0909 08:02:35.353185 18126 registrar.cpp:422] Attempting to update the
'registry'
I0909 08:02:35.354152 18126 log.cpp:680] Attempting to append 120 bytes to the
log
I0909 08:02:35.354195 18126 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0909 08:02:35.354416 18126 replica.cpp:508] Replica received write request for
position 1
I0909 08:02:35.351579 18127 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0909 08:02:35.354558 18127 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 2.984795ms
I0909 08:02:35.360254 18126 leveldb.cpp:343] Persisting action (137 bytes) to
leveldb took 5.811986ms
I0909 08:02:35.360285 18126 replica.cpp:676] Persisted action at 1
I0909 08:02:35.364126 18132 replica.cpp:655] Replica received learned notice
for position 1
I0909 08:02:35.369856 18132 leveldb.cpp:343] Persisting action (139 bytes) to
leveldb took 5.702756ms
I0909 08:02:35.369899 18132 replica.cpp:676] Persisted action at 1
I0909 08:02:35.369910 18132 replica.cpp:661] Replica learned APPEND action at
position 1
I0909 08:02:35.370209 18132 registrar.cpp:479] Successfully updated 'registry'
I0909 08:02:35.370311 18132 registrar.cpp:372] Successfully recovered registrar
I0909 08:02:35.370477 18132 log.cpp:699] Attempting to truncate the log to 1
I0909 08:02:35.370553 18132 master.cpp:1070] Recovered 0 slaves from the
Registry (84B) ; allowing 10mins for slaves to re-register
I0909 08:02:35.370594 18132 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0909 08:02:35.371201 18127 replica.cpp:508] Replica received write request for
position 2
I0909 08:02:35.376760 18127 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 5.264501ms
I0909 08:02:35.377105 18127 replica.cpp:676] Persisted action at 2
I0909 08:02:35.377770 18127 replica.cpp:655] Replica received learned notice
for position 2
I0909 08:02:35.383363 18127 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 5.272769ms
I0909 08:02:35.383818 18127 leveldb.cpp:401] Deleting ~1 keys from leveldb took
28148ns
I0909 08:02:35.384137 18127 replica.cpp:676] Persisted action at 2
I0909 08:02:35.384399 18127 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0909 08:02:35.396512 18127 slave.cpp:167] Slave started on 64)@127.0.1.1:44005
I0909 08:02:35.654770 18131 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0909 08:02:35.654847 18131 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 104933ns
I0909 08:02:35.654974 18127 credentials.hpp:84] Loading credential for
authentication from '/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/credential'
I0909 08:02:35.655097 18127 slave.cpp:274] Slave using credential for:
test-principal
I0909 08:02:35.655203 18127 slave.cpp:287] Slave resources: cpus(*):3;
mem(*):1024; disk(*):25116; ports(*):[31000-32000]
I0909 08:02:35.655274 18127 slave.cpp:315] Slave hostname: precise
I0909 08:02:35.655285 18127 slave.cpp:316] Slave checkpoint: false
I0909 08:02:35.655804 18127 state.cpp:33] Recovering state from
'/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/meta'
I0909 08:02:35.655913 18127 status_update_manager.cpp:193] Recovering status
update manager
I0909 08:02:35.656005 18127 slave.cpp:3202] Finished recovery
I0909 08:02:35.656251 18127 slave.cpp:598] New master detected at
[email protected]:44005
I0909 08:02:35.656285 18127 slave.cpp:672] Authenticating with master
[email protected]:44005
I0909 08:02:35.656325 18127 slave.cpp:645] Detecting new master
I0909 08:02:35.656358 18127 status_update_manager.cpp:167] New master detected
at [email protected]:44005
I0909 08:02:35.656389 18127 authenticatee.hpp:128] Creating new client SASL
connection
I0909 08:02:35.656563 18127 master.cpp:3653] Authenticating
slave(64)@127.0.1.1:44005
I0909 08:02:35.656651 18127 authenticator.hpp:156] Creating new server SASL
connection
I0909 08:02:35.656770 18127 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 08:02:35.656796 18127 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 08:02:35.656822 18127 authenticator.hpp:262] Received SASL authentication
start
I0909 08:02:35.656858 18127 authenticator.hpp:384] Authentication requires more
steps
I0909 08:02:35.656883 18127 authenticatee.hpp:265] Received SASL authentication
step
I0909 08:02:35.656924 18127 authenticator.hpp:290] Received SASL authentication
step
I0909 08:02:35.656960 18127 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 08:02:35.656971 18127 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 08:02:35.656982 18127 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 08:02:35.656997 18127 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 08:02:35.657004 18127 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.657008 18127 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.657019 18127 authenticator.hpp:376] Authentication success
I0909 08:02:35.657047 18127 authenticatee.hpp:305] Authentication success
I0909 08:02:35.657073 18127 master.cpp:3693] Successfully authenticated
principal 'test-principal' at slave(64)@127.0.1.1:44005
I0909 08:02:35.657145 18127 slave.cpp:729] Successfully authenticated with
master [email protected]:44005
I0909 08:02:35.657183 18127 slave.cpp:980] Will retry registration in
19.238717ms if necessary
I0909 08:02:35.657276 18128 master.cpp:2843] Registering slave at
slave(64)@127.0.1.1:44005 (precise) with id
20140909-080235-16842879-44005-18112-0
I0909 08:02:35.657389 18128 registrar.cpp:422] Attempting to update the
'registry'
I0909 08:02:35.658382 18130 log.cpp:680] Attempting to append 295 bytes to the
log
I0909 08:02:35.658432 18130 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 3
I0909 08:02:35.658635 18130 replica.cpp:508] Replica received write request for
position 3
I0909 08:02:35.660959 18112 sched.cpp:137] Version: 0.21.0
I0909 08:02:35.661093 18126 sched.cpp:233] New master detected at
[email protected]:44005
I0909 08:02:35.661111 18126 sched.cpp:283] Authenticating with master
[email protected]:44005
I0909 08:02:35.661175 18126 authenticatee.hpp:128] Creating new client SASL
connection
I0909 08:02:35.661306 18126 master.cpp:3653] Authenticating
[email protected]:44005
I0909 08:02:35.661376 18126 authenticator.hpp:156] Creating new server SASL
connection
I0909 08:02:35.661466 18126 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 08:02:35.661483 18126 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 08:02:35.661504 18126 authenticator.hpp:262] Received SASL authentication
start
I0909 08:02:35.661530 18126 authenticator.hpp:384] Authentication requires more
steps
I0909 08:02:35.661552 18126 authenticatee.hpp:265] Received SASL authentication
step
I0909 08:02:35.661579 18126 authenticator.hpp:290] Received SASL authentication
step
I0909 08:02:35.661592 18126 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 08:02:35.661598 18126 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 08:02:35.661607 18126 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 08:02:35.661613 18126 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 08:02:35.661619 18126 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.661623 18126 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.661633 18126 authenticator.hpp:376] Authentication success
I0909 08:02:35.661653 18126 authenticatee.hpp:305] Authentication success
I0909 08:02:35.661672 18126 master.cpp:3693] Successfully authenticated
principal 'test-principal' at
[email protected]:44005
I0909 08:02:35.661730 18126 sched.cpp:357] Successfully authenticated with
master [email protected]:44005
I0909 08:02:35.661741 18126 sched.cpp:476] Sending registration request to
[email protected]:44005
I0909 08:02:35.661782 18126 master.cpp:1331] Received registration request from
[email protected]:44005
I0909 08:02:35.661798 18126 master.cpp:1291] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0909 08:02:35.661917 18126 master.cpp:1390] Registering framework
20140909-080235-16842879-44005-18112-0000 at
[email protected]:44005
I0909 08:02:35.662017 18126 sched.cpp:407] Framework registered with
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.662039 18126 sched.cpp:421] Scheduler::registered took 9070ns
I0909 08:02:35.662119 18126 hierarchical_allocator_process.hpp:329] Added
framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.662130 18126 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0909 08:02:35.662135 18126 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 5558ns
I0909 08:02:35.672230 18130 leveldb.cpp:343] Persisting action (314 bytes) to
leveldb took 13.567526ms
I0909 08:02:35.672268 18130 replica.cpp:676] Persisted action at 3
I0909 08:02:35.672483 18130 replica.cpp:655] Replica received learned notice
for position 3
I0909 08:02:35.677322 18132 slave.cpp:980] Will retry registration in
14.890338ms if necessary
I0909 08:02:35.677399 18132 master.cpp:2831] Ignoring register slave message
from slave(64)@127.0.1.1:44005 (precise) as admission is already in progress
I0909 08:02:35.680881 18130 leveldb.cpp:343] Persisting action (316 bytes) to
leveldb took 8.376798ms
I0909 08:02:35.680908 18130 replica.cpp:676] Persisted action at 3
I0909 08:02:35.680917 18130 replica.cpp:661] Replica learned APPEND action at
position 3
I0909 08:02:35.681252 18130 registrar.cpp:479] Successfully updated 'registry'
I0909 08:02:35.681330 18130 log.cpp:699] Attempting to truncate the log to 3
I0909 08:02:35.681385 18130 master.cpp:2883] Registered slave
20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise)
I0909 08:02:35.681399 18130 master.cpp:4126] Adding slave
20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise)
with cpus(*):3; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
I0909 08:02:35.681504 18130 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I0909 08:02:35.681570 18130 slave.cpp:763] Registered with master
[email protected]:44005; given slave ID 20140909-080235-16842879-44005-18112-0
I0909 08:02:35.681689 18130 slave.cpp:2329] Received ping from
slave-observer(50)@127.0.1.1:44005
I0909 08:02:35.681753 18130 hierarchical_allocator_process.hpp:442] Added slave
20140909-080235-16842879-44005-18112-0 (precise) with cpus(*):3; mem(*):1024;
disk(*):25116; ports(*):[31000-32000] (and cpus(*):3; mem(*):1024;
disk(*):25116; ports(*):[31000-32000] available)
I0909 08:02:35.681808 18130 hierarchical_allocator_process.hpp:734] Offering
cpus(*):3; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 to framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.681892 18130 hierarchical_allocator_process.hpp:679] Performed
allocation for slave 20140909-080235-16842879-44005-18112-0 in 109580ns
I0909 08:02:35.681968 18130 master.hpp:861] Adding offer
20140909-080235-16842879-44005-18112-0 with resources cpus(*):3; mem(*):1024;
disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.682014 18130 master.cpp:3600] Sending 1 offers to framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.682443 18130 sched.cpp:544] Scheduler::resourceOffers took
254258ns
I0909 08:02:35.682633 18130 master.hpp:871] Removing offer
20140909-080235-16842879-44005-18112-0 with resources cpus(*):3; mem(*):1024;
disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.682684 18130 master.cpp:2201] Processing reply for offers: [
20140909-080235-16842879-44005-18112-0 ] on slave
20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise)
for framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.682708 18130 master.cpp:2284] Authorizing framework principal
'test-principal' to launch task 0 as user 'jenkins'
I0909 08:02:35.682971 18130 replica.cpp:508] Replica received write request for
position 4
I0909 08:02:35.683132 18132 master.hpp:833] Adding task 0 with resources
cpus(*):2; mem(*):512 on slave 20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.683159 18132 master.cpp:2350] Launching task 0 of framework
20140909-080235-16842879-44005-18112-0000 with resources cpus(*):2; mem(*):512
on slave 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005
(precise)
I0909 08:02:35.683363 18132 slave.cpp:1011] Got assigned task 0 for framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.683580 18132 slave.cpp:1121] Launching task 0 for framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.684833 18133 hierarchical_allocator_process.hpp:563] Recovered
cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000] (total
allocatable: cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000]) on
slave 20140909-080235-16842879-44005-18112-0 from framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.684864 18133 hierarchical_allocator_process.hpp:599] Framework
20140909-080235-16842879-44005-18112-0000 filtered slave
20140909-080235-16842879-44005-18112-0 for 5secs
I0909 08:02:35.686401 18132 exec.cpp:132] Version: 0.21.0
I0909 08:02:35.686848 18128 exec.cpp:182] Executor started at:
executor(8)@127.0.1.1:44005 with pid 18112
I0909 08:02:35.687095 18132 slave.cpp:1231] Queuing task '0' for executor
executor-1 of framework '20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.687302 18132 slave.cpp:552] Successfully attached file
'/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/slaves/20140909-080235-16842879-44005-18112-0/frameworks/20140909-080235-16842879-44005-18112-0000/executors/executor-1/runs/c4458e43-94ee-4b5e-bd74-5d39a09deff6'
I0909 08:02:35.687568 18132 slave.cpp:1741] Got registration for executor
'executor-1' of framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.687893 18127 exec.cpp:206] Executor registered on slave
20140909-080235-16842879-44005-18112-0
I0909 08:02:35.688789 18127 exec.cpp:218] Executor::registered took 15015ns
I0909 08:02:35.688977 18132 slave.cpp:1859] Flushing queued task 0 for executor
'executor-1' of framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.689260 18133 exec.cpp:293] Executor asked to run task '0'
I0909 08:02:35.689441 18133 exec.cpp:302] Executor::launchTask took 24599ns
I0909 08:02:35.691651 18112 sched.cpp:137] Version: 0.21.0
I0909 08:02:35.691946 18131 sched.cpp:233] New master detected at
[email protected]:44005
I0909 08:02:35.692126 18131 sched.cpp:283] Authenticating with master
[email protected]:44005
I0909 08:02:35.692399 18131 authenticatee.hpp:128] Creating new client SASL
connection
I0909 08:02:35.692791 18131 master.cpp:3653] Authenticating
[email protected]:44005
I0909 08:02:35.693068 18131 authenticator.hpp:156] Creating new server SASL
connection
I0909 08:02:35.693351 18131 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 08:02:35.693532 18131 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 08:02:35.693739 18131 authenticator.hpp:262] Received SASL authentication
start
I0909 08:02:35.693979 18131 authenticator.hpp:384] Authentication requires more
steps
I0909 08:02:35.694202 18131 authenticatee.hpp:265] Received SASL authentication
step
I0909 08:02:35.694449 18131 authenticator.hpp:290] Received SASL authentication
step
I0909 08:02:35.694633 18131 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 08:02:35.694792 18131 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 08:02:35.694980 18131 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 08:02:35.695158 18131 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'precise' server FQDN: 'precise'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 08:02:35.695369 18131 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.695724 18131 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 08:02:35.695907 18131 authenticator.hpp:376] Authentication success
I0909 08:02:35.696117 18128 authenticatee.hpp:305] Authentication success
I0909 08:02:35.698509 18130 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 15.520863ms
I0909 08:02:35.698698 18130 replica.cpp:676] Persisted action at 4
I0909 08:02:35.698940 18128 sched.cpp:357] Successfully authenticated with
master [email protected]:44005
I0909 08:02:35.699095 18126 master.cpp:3693] Successfully authenticated
principal 'test-principal' at
[email protected]:44005
I0909 08:02:35.699354 18130 replica.cpp:655] Replica received learned notice
for position 4
I0909 08:02:35.699973 18128 sched.cpp:476] Sending registration request to
[email protected]:44005
I0909 08:02:35.700265 18128 master.cpp:1331] Received registration request from
[email protected]:44005
I0909 08:02:35.700515 18128 master.cpp:1291] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0909 08:02:35.700809 18128 master.cpp:1390] Registering framework
20140909-080235-16842879-44005-18112-0001 at
[email protected]:44005
I0909 08:02:35.701037 18133 sched.cpp:407] Framework registered with
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.701211 18133 sched.cpp:421] Scheduler::registered took 11991ns
I0909 08:02:35.701488 18131 hierarchical_allocator_process.hpp:329] Added
framework 20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.701728 18131 hierarchical_allocator_process.hpp:734] Offering
cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 to framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.701992 18131 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 297969ns
I0909 08:02:35.702229 18128 master.hpp:861] Adding offer
20140909-080235-16842879-44005-18112-1 with resources cpus(*):1; mem(*):512;
disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.702481 18128 master.cpp:3600] Sending 1 offers to framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.702901 18129 sched.cpp:544] Scheduler::resourceOffers took
127949ns
I0909 08:02:35.703305 18128 master.hpp:871] Removing offer
20140909-080235-16842879-44005-18112-1 with resources cpus(*):1; mem(*):512;
disk(*):25116; ports(*):[31000-32000] on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.703629 18128 master.cpp:2201] Processing reply for offers: [
20140909-080235-16842879-44005-18112-1 ] on slave
20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise)
for framework 20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.703908 18128 master.cpp:2284] Authorizing framework principal
'test-principal' to launch task 0 as user 'jenkins'
I0909 08:02:35.703789 18132 slave.cpp:2542] Monitoring executor 'executor-1' of
framework '20140909-080235-16842879-44005-18112-0000' in container
'c4458e43-94ee-4b5e-bd74-5d39a09deff6'
I0909 08:02:35.704763 18128 master.hpp:833] Adding task 0 with resources
cpus(*):1; mem(*):256 on slave 20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.704951 18128 master.cpp:2350] Launching task 0 of framework
20140909-080235-16842879-44005-18112-0001 with resources cpus(*):1; mem(*):256
on slave 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005
(precise)
I0909 08:02:35.705255 18129 slave.cpp:1011] Got assigned task 0 for framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.705582 18129 slave.cpp:1121] Launching task 0 for framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.707756 18129 exec.cpp:132] Version: 0.21.0
I0909 08:02:35.708035 18130 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 8.127072ms
I0909 08:02:35.708281 18130 leveldb.cpp:401] Deleting ~2 keys from leveldb took
28817ns
I0909 08:02:35.708459 18130 replica.cpp:676] Persisted action at 4
I0909 08:02:35.708632 18130 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I0909 08:02:35.708869 18133 exec.cpp:182] Executor started at:
executor(9)@127.0.1.1:44005 with pid 18112
I0909 08:02:35.709120 18127 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 35083ns
I0909 08:02:35.709511 18129 slave.cpp:1231] Queuing task '0' for executor
executor-2 of framework '20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.709707 18129 slave.cpp:552] Successfully attached file
'/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/slaves/20140909-080235-16842879-44005-18112-0/frameworks/20140909-080235-16842879-44005-18112-0001/executors/executor-2/runs/7654870b-fd36-40b2-aac7-37b1bcfa821e'
I0909 08:02:35.709913 18129 slave.cpp:1741] Got registration for executor
'executor-2' of framework 20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.710188 18129 slave.cpp:1859] Flushing queued task 0 for executor
'executor-2' of framework 20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.710516 18129 slave.cpp:2542] Monitoring executor 'executor-2' of
framework '20140909-080235-16842879-44005-18112-0001' in container
'7654870b-fd36-40b2-aac7-37b1bcfa821e'
I0909 08:02:35.710321 18130 exec.cpp:206] Executor registered on slave
20140909-080235-16842879-44005-18112-0
I0909 08:02:35.711678 18130 exec.cpp:218] Executor::registered took 14355ns
I0909 08:02:35.711987 18130 exec.cpp:293] Executor asked to run task '0'
I0909 08:02:35.715551 18130 exec.cpp:302] Executor::launchTask took 3.40476ms
I0909 08:02:35.716006 18131 sched.cpp:745] Stopping framework
'20140909-080235-16842879-44005-18112-0000'
I0909 08:02:35.716292 18128 master.cpp:1640] Asked to unregister framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.716490 18127 hierarchical_allocator_process.hpp:563] Recovered
mem(*):256; disk(*):25116; ports(*):[31000-32000] (total allocatable:
mem(*):256; disk(*):25116; ports(*):[31000-32000]) on slave
20140909-080235-16842879-44005-18112-0 from framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.716792 18127 hierarchical_allocator_process.hpp:599] Framework
20140909-080235-16842879-44005-18112-0001 filtered slave
20140909-080235-16842879-44005-18112-0 for 5secs
I0909 08:02:35.717018 18128 master.cpp:3976] Removing framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.717269 18128 master.hpp:851] Removing task 0 with resources
cpus(*):2; mem(*):512 on slave 20140909-080235-16842879-44005-18112-0 (precise)
W0909 08:02:35.717607 18128 master.cpp:4419] Removing task 0 of framework
20140909-080235-16842879-44005-18112-0000 and slave
20140909-080235-16842879-44005-18112-0 in non-terminal state TASK_STAGING
I0909 08:02:35.717470 18131 hierarchical_allocator_process.hpp:405] Deactivated
framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.718065 18131 hierarchical_allocator_process.hpp:563] Recovered
cpus(*):2; mem(*):512 (total allocatable: mem(*):768; disk(*):25116;
ports(*):[31000-32000]; cpus(*):2) on slave
20140909-080235-16842879-44005-18112-0 from framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.717438 18132 slave.cpp:1414] Asked to shut down framework
20140909-080235-16842879-44005-18112-0000 by [email protected]:44005
I0909 08:02:35.718444 18132 slave.cpp:1439] Shutting down framework
20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.718621 18132 slave.cpp:2882] Shutting down executor 'executor-1'
of framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.718843 18133 exec.cpp:379] Executor asked to shutdown
I0909 08:02:35.719022 18133 exec.cpp:394] Executor::shutdown took 13745ns
I0909 08:02:35.722009 18128 hierarchical_allocator_process.hpp:360] Removed
framework 20140909-080235-16842879-44005-18112-0000
I0909 08:02:35.830785 18131 hierarchical_allocator_process.hpp:734] Offering
mem(*):768; disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave
20140909-080235-16842879-44005-18112-0 to framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.830940 18131 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 218030ns
I0909 08:02:35.831056 18127 master.hpp:861] Adding offer
20140909-080235-16842879-44005-18112-2 with resources mem(*):768;
disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.831115 18127 master.cpp:3600] Sending 1 offers to framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.831248 18127 sched.cpp:544] Scheduler::resourceOffers took
18178ns
I0909 08:02:35.831387 18112 master.cpp:650] Master terminating
I0909 08:02:35.831441 18112 master.hpp:851] Removing task 0 with resources
cpus(*):1; mem(*):256 on slave 20140909-080235-16842879-44005-18112-0 (precise)
W0909 08:02:35.831488 18112 master.cpp:4419] Removing task 0 of framework
20140909-080235-16842879-44005-18112-0001 and slave
20140909-080235-16842879-44005-18112-0 in non-terminal state TASK_STAGING
I0909 08:02:35.831573 18112 master.hpp:871] Removing offer
20140909-080235-16842879-44005-18112-2 with resources mem(*):768;
disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave
20140909-080235-16842879-44005-18112-0 (precise)
I0909 08:02:35.832608 18112 slave.cpp:475] Slave terminating
I0909 08:02:35.832630 18112 slave.cpp:1414] Asked to shut down framework
20140909-080235-16842879-44005-18112-0000 by @0.0.0.0:0
W0909 08:02:35.832643 18112 slave.cpp:1435] Ignoring shutdown framework
20140909-080235-16842879-44005-18112-0000 because it is terminating
I0909 08:02:35.832648 18112 slave.cpp:1414] Asked to shut down framework
20140909-080235-16842879-44005-18112-0001 by @0.0.0.0:0
I0909 08:02:35.832654 18112 slave.cpp:1439] Shutting down framework
20140909-080235-16842879-44005-18112-0001
I0909 08:02:35.832664 18112 slave.cpp:2882] Shutting down executor 'executor-2'
of framework 20140909-080235-16842879-44005-18112-0001
tests/allocator_tests.cpp:1444: Failure
Actual function call count doesn't match EXPECT_CALL(this->allocator,
resourcesRecovered(_, _, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] AllocatorTest/0.FrameworkExited, where TypeParam =
mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter,
mesos::internal::master::allocator::DRFSorter> (756 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
