Vinod Kone created MESOS-1422:
---------------------------------
Summary: AllocatorTest/0.SchedulerFailover test is flaky
Key: MESOS-1422
URL: https://issues.apache.org/jira/browse/MESOS-1422
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.19.0
Reporter: Vinod Kone
Fix For: 0.19.0
[ RUN ] AllocatorTest/0.SchedulerFailover
Using temporary directory '/tmp/AllocatorTest_0_SchedulerFailover_c1BnNj'
I0527 18:39:49.033879 22750 leveldb.cpp:176] Opened db in 4.280975ms
I0527 18:39:49.034219 22750 leveldb.cpp:183] Compacted db in 315241ns
I0527 18:39:49.034234 22750 leveldb.cpp:198] Created db iterator in 4763ns
I0527 18:39:49.034240 22750 leveldb.cpp:204] Seeked to beginning of db in 776ns
I0527 18:39:49.034246 22750 leveldb.cpp:273] Iterated through 0 keys in the db
in 313ns
I0527 18:39:49.034261 22750 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0527 18:39:49.034559 22776 recover.cpp:425] Starting replica recovery
I0527 18:39:49.034740 22777 recover.cpp:451] Replica is in EMPTY status
I0527 18:39:49.035194 22773 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0527 18:39:49.035333 22774 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0527 18:39:49.035465 22777 recover.cpp:542] Updating replica status to STARTING
I0527 18:39:49.036082 22770 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 554995ns
I0527 18:39:49.036095 22770 replica.cpp:320] Persisted replica status to
STARTING
I0527 18:39:49.036195 22770 recover.cpp:451] Replica is in STARTING status
I0527 18:39:49.036375 22775 master.cpp:272] Master
20140527-183949-143311683-39317-22750 (minerva.apache.org) started on
67.195.138.8:39317
I0527 18:39:49.036389 22775 master.cpp:309] Master only allowing authenticated
frameworks to register
I0527 18:39:49.036396 22775 master.cpp:314] Master only allowing authenticated
slaves to register
I0527 18:39:49.036404 22775 credentials.hpp:35] Loading credentials for
authentication from '/tmp/AllocatorTest_0_SchedulerFailover_c1BnNj/credentials'
I0527 18:39:49.036476 22775 master.cpp:340] Master enabling authorization
I0527 18:39:49.036633 22777 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0527 18:39:49.036784 22777 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0527 18:39:49.037078 22776 hierarchical_allocator_process.hpp:301]
Initializing hierarchical allocator process with master :
[email protected]:39317
I0527 18:39:49.037120 22774 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0527 18:39:49.037168 22770 master.cpp:936] The newly elected leader is
[email protected]:39317 with id 20140527-183949-143311683-39317-22750
I0527 18:39:49.037185 22770 master.cpp:949] Elected as the leading master!
I0527 18:39:49.037194 22770 master.cpp:767] Recovering from registrar
I0527 18:39:49.037246 22777 registrar.cpp:313] Recovering registrar
I0527 18:39:49.037331 22772 recover.cpp:542] Updating replica status to VOTING
I0527 18:39:49.037518 22777 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 115462ns
I0527 18:39:49.037530 22777 replica.cpp:320] Persisted replica status to VOTING
I0527 18:39:49.037576 22772 recover.cpp:556] Successfully joined the Paxos group
I0527 18:39:49.037653 22772 recover.cpp:440] Recover process terminated
I0527 18:39:49.037768 22777 log.cpp:656] Attempting to start the writer
I0527 18:39:49.038187 22777 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0527 18:39:49.038281 22777 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 82264ns
I0527 18:39:49.038292 22777 replica.cpp:342] Persisted promised to 1
I0527 18:39:49.038519 22770 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0527 18:39:49.039046 22774 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0527 18:39:49.039160 22774 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 100359ns
I0527 18:39:49.039171 22774 replica.cpp:676] Persisted action at 0
I0527 18:39:49.039580 22777 replica.cpp:508] Replica received write request for
position 0
I0527 18:39:49.039607 22777 leveldb.cpp:438] Reading position from leveldb took
14246ns
I0527 18:39:49.039716 22777 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 94200ns
I0527 18:39:49.039727 22777 replica.cpp:676] Persisted action at 0
I0527 18:39:49.039923 22771 replica.cpp:655] Replica received learned notice
for position 0
I0527 18:39:49.040056 22771 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 115341ns
I0527 18:39:49.040067 22771 replica.cpp:676] Persisted action at 0
I0527 18:39:49.040077 22771 replica.cpp:661] Replica learned NOP action at
position 0
I0527 18:39:49.040308 22774 log.cpp:672] Writer started with ending position 0
I0527 18:39:49.040755 22775 leveldb.cpp:438] Reading position from leveldb took
7629ns
I0527 18:39:49.041780 22776 registrar.cpp:346] Successfully fetched the
registry (0B)
I0527 18:39:49.041805 22776 registrar.cpp:422] Attempting to update the
'registry'
I0527 18:39:49.042788 22773 log.cpp:680] Attempting to append 137 bytes to the
log
I0527 18:39:49.042891 22771 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0527 18:39:49.043326 22772 replica.cpp:508] Replica received write request for
position 1
I0527 18:39:49.043556 22772 leveldb.cpp:343] Persisting action (156 bytes) to
leveldb took 199861ns
I0527 18:39:49.043570 22772 replica.cpp:676] Persisted action at 1
I0527 18:39:49.043906 22774 replica.cpp:655] Replica received learned notice
for position 1
I0527 18:39:49.044050 22774 leveldb.cpp:343] Persisting action (158 bytes) to
leveldb took 130432ns
I0527 18:39:49.044062 22774 replica.cpp:676] Persisted action at 1
I0527 18:39:49.044070 22774 replica.cpp:661] Replica learned APPEND action at
position 1
I0527 18:39:49.044378 22772 registrar.cpp:479] Successfully updated 'registry'
I0527 18:39:49.044461 22772 registrar.cpp:372] Successfully recovered registrar
I0527 18:39:49.044589 22777 log.cpp:699] Attempting to truncate the log to 1
I0527 18:39:49.044595 22770 master.cpp:794] Recovered 0 slaves from the
Registry (99B) ; allowing 10mins for slaves to re-register
I0527 18:39:49.044667 22771 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0527 18:39:49.045047 22775 replica.cpp:508] Replica received write request for
position 2
I0527 18:39:49.057709 22777 slave.cpp:143] Slave started on
62)@67.195.138.8:39317
I0527 18:39:49.293050 22777 credentials.hpp:35] Loading credentials for
authentication from '/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/credential'
I0527 18:39:49.059094 22750 sched.cpp:121] Version: 0.19.0
I0527 18:39:49.293115 22777 slave.cpp:242] Slave using credential for:
test-principal
I0527 18:39:49.293184 22775 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 145967ns
I0527 18:39:49.293205 22775 replica.cpp:676] Persisted action at 2
I0527 18:39:49.293220 22777 slave.cpp:255] Slave resources: cpus(*):3;
mem(*):1024; disk(*):23038; ports(*):[31000-32000]
I0527 18:39:49.293289 22777 slave.cpp:283] Slave hostname: minerva.apache.org
I0527 18:39:49.293298 22777 slave.cpp:284] Slave checkpoint: false
I0527 18:39:49.293311 22774 sched.cpp:217] New master detected at
[email protected]:39317
I0527 18:39:49.293333 22774 sched.cpp:268] Authenticating with master
[email protected]:39317
I0527 18:39:49.293460 22770 replica.cpp:655] Replica received learned notice
for position 2
I0527 18:39:49.293498 22776 authenticatee.hpp:128] Creating new client SASL
connection
I0527 18:39:49.293598 22770 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 124005ns
I0527 18:39:49.293627 22770 leveldb.cpp:401] Deleting ~1 keys from leveldb took
11392ns
I0527 18:39:49.293637 22770 replica.cpp:676] Persisted action at 2
I0527 18:39:49.293645 22770 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0527 18:39:49.293772 22773 state.cpp:33] Recovering state from
'/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/meta'
I0527 18:39:49.293797 22776 master.cpp:2896] Authenticating
scheduler(59)@67.195.138.8:39317
I0527 18:39:49.293954 22773 authenticator.hpp:156] Creating new server SASL
connection
I0527 18:39:49.294090 22773 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0527 18:39:49.294107 22773 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0527 18:39:49.294147 22773 authenticator.hpp:262] Received SASL authentication
start
I0527 18:39:49.294191 22773 authenticator.hpp:384] Authentication requires more
steps
I0527 18:39:49.294215 22773 authenticatee.hpp:265] Received SASL authentication
step
I0527 18:39:49.294277 22773 authenticator.hpp:290] Received SASL authentication
step
I0527 18:39:49.294292 22773 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0527 18:39:49.294302 22773 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0527 18:39:49.294312 22773 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0527 18:39:49.294320 22773 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0527 18:39:49.294327 22773 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.294332 22773 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.294340 22773 authenticator.hpp:376] Authentication success
I0527 18:39:49.294422 22770 authenticatee.hpp:305] Authentication success
I0527 18:39:49.294440 22774 master.cpp:2936] Successfully authenticated
principal 'test-principal' at scheduler(59)@67.195.138.8:39317
I0527 18:39:49.294459 22773 status_update_manager.cpp:193] Recovering status
update manager
I0527 18:39:49.294543 22770 sched.cpp:342] Successfully authenticated with
master [email protected]:39317
I0527 18:39:49.294567 22770 sched.cpp:461] Sending registration request to
[email protected]:39317
W0527 18:39:49.294620 22774 master.cpp:1008] Framework at
scheduler(59)@67.195.138.8:39317 does not specify principal in its FrameworkInfo
I0527 18:39:49.294633 22774 master.cpp:1020] Received registration request from
scheduler(59)@67.195.138.8:39317
I0527 18:39:49.294677 22774 master.cpp:1038] Registering framework
20140527-183949-143311683-39317-22750-0000 at scheduler(59)@67.195.138.8:39317
I0527 18:39:49.294693 22775 slave.cpp:2988] Finished recovery
I0527 18:39:49.294775 22773 sched.cpp:392] Framework registered with
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.294800 22773 sched.cpp:406] Scheduler::registered took 14760ns
I0527 18:39:49.294837 22774 hierarchical_allocator_process.hpp:331] Added
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.294847 22774 hierarchical_allocator_process.hpp:725] No
resources available to allocate!
I0527 18:39:49.294853 22774 hierarchical_allocator_process.hpp:687] Performed
allocation for 0 slaves in 5683ns
I0527 18:39:49.295058 22777 slave.cpp:536] New master detected at
[email protected]:39317
I0527 18:39:49.295092 22777 slave.cpp:612] Authenticating with master
[email protected]:39317
I0527 18:39:49.295135 22775 status_update_manager.cpp:167] New master detected
at [email protected]:39317
I0527 18:39:49.295156 22777 slave.cpp:585] Detecting new master
I0527 18:39:49.295173 22776 authenticatee.hpp:128] Creating new client SASL
connection
I0527 18:39:49.295315 22774 master.cpp:2896] Authenticating
slave(62)@67.195.138.8:39317
I0527 18:39:49.295389 22777 authenticator.hpp:156] Creating new server SASL
connection
I0527 18:39:49.295526 22775 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0527 18:39:49.295543 22775 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0527 18:39:49.295580 22776 authenticator.hpp:262] Received SASL authentication
start
I0527 18:39:49.295622 22776 authenticator.hpp:384] Authentication requires more
steps
I0527 18:39:49.295650 22776 authenticatee.hpp:265] Received SASL authentication
step
I0527 18:39:49.295740 22774 authenticator.hpp:290] Received SASL authentication
step
I0527 18:39:49.295789 22774 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0527 18:39:49.295800 22774 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0527 18:39:49.295809 22774 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0527 18:39:49.295819 22774 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0527 18:39:49.295825 22774 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.295830 22774 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.295840 22774 authenticator.hpp:376] Authentication success
I0527 18:39:49.295903 22773 authenticatee.hpp:305] Authentication success
I0527 18:39:49.295922 22774 master.cpp:2936] Successfully authenticated
principal 'test-principal' at slave(62)@67.195.138.8:39317
I0527 18:39:49.296052 22773 slave.cpp:669] Successfully authenticated with
master [email protected]:39317
I0527 18:39:49.296100 22773 slave.cpp:903] Will retry registration in
3.726421ms if necessary
I0527 18:39:49.296176 22770 master.cpp:2212] Registering slave at
slave(62)@67.195.138.8:39317 (minerva.apache.org) with id
20140527-183949-143311683-39317-22750-0
I0527 18:39:49.296330 22777 registrar.cpp:422] Attempting to update the
'registry'
I0527 18:39:49.297399 22775 log.cpp:680] Attempting to append 333 bytes to the
log
I0527 18:39:49.297467 22771 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 3
I0527 18:39:49.297865 22777 replica.cpp:508] Replica received write request for
position 3
I0527 18:39:49.300346 22775 slave.cpp:903] Will retry registration in
37.541739ms if necessary
I0527 18:39:49.300380 22773 master.cpp:2200] Ignoring register slave message
from slave(62)@67.195.138.8:39317 (minerva.apache.org) as admission is already
in progress
I0527 18:39:49.540730 22777 leveldb.cpp:343] Persisting action (352 bytes) to
leveldb took 169361ns
I0527 18:39:49.540743 22777 replica.cpp:676] Persisted action at 3
I0527 18:39:49.540990 22777 replica.cpp:655] Replica received learned notice
for position 3
I0527 18:39:49.541149 22777 leveldb.cpp:343] Persisting action (354 bytes) to
leveldb took 138801ns
I0527 18:39:49.541162 22777 replica.cpp:676] Persisted action at 3
I0527 18:39:49.541172 22777 replica.cpp:661] Replica learned APPEND action at
position 3
I0527 18:39:49.541625 22776 registrar.cpp:479] Successfully updated 'registry'
I0527 18:39:49.541729 22771 log.cpp:699] Attempting to truncate the log to 3
I0527 18:39:49.541784 22772 master.cpp:2252] Registered slave
20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317
(minerva.apache.org)
I0527 18:39:49.541805 22772 master.cpp:3382] Adding slave
20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317
(minerva.apache.org) with cpus(*):3; mem(*):1024; disk(*):23038;
ports(*):[31000-32000]
I0527 18:39:49.541823 22777 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I0527 18:39:49.541868 22771 slave.cpp:703] Registered with master
[email protected]:39317; given slave ID
20140527-183949-143311683-39317-22750-0
I0527 18:39:49.542100 22771 hierarchical_allocator_process.hpp:444] Added slave
20140527-183949-143311683-39317-22750-0 (minerva.apache.org) with cpus(*):3;
mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):3; mem(*):1024;
disk(*):23038; ports(*):[31000-32000] available)
I0527 18:39:49.542166 22771 hierarchical_allocator_process.hpp:751] Offering
cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave
20140527-183949-143311683-39317-22750-0 to framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.542217 22770 replica.cpp:508] Replica received write request for
position 4
I0527 18:39:49.542307 22771 hierarchical_allocator_process.hpp:707] Performed
allocation for slave 20140527-183949-143311683-39317-22750-0 in 170025ns
I0527 18:39:49.542379 22773 master.hpp:669] Adding offer
20140527-183949-143311683-39317-22750-0 with resources cpus(*):3; mem(*):1024;
disk(*):23038; ports(*):[31000-32000] on slave
20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
I0527 18:39:49.542404 22770 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 167475ns
I0527 18:39:49.542417 22770 replica.cpp:676] Persisted action at 4
I0527 18:39:49.542420 22773 master.cpp:2843] Sending 1 offers to framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.542621 22777 replica.cpp:655] Replica received learned notice
for position 4
I0527 18:39:49.542757 22777 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 118653ns
I0527 18:39:49.542734 22775 sched.cpp:529] Scheduler::resourceOffers took
174931ns
I0527 18:39:49.542785 22777 leveldb.cpp:401] Deleting ~2 keys from leveldb took
17584ns
I0527 18:39:49.542794 22777 replica.cpp:676] Persisted action at 4
I0527 18:39:49.542801 22777 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I0527 18:39:49.543007 22776 master.hpp:679] Removing offer
20140527-183949-143311683-39317-22750-0 with resources cpus(*):3; mem(*):1024;
disk(*):23038; ports(*):[31000-32000] on slave
20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
I0527 18:39:49.543071 22776 master.cpp:1877] Processing reply for offers: [
20140527-183949-143311683-39317-22750-0 ] on slave
20140527-183949-143311683-39317-22750-0 at slave(62)@67.195.138.8:39317
(minerva.apache.org) for framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.543162 22776 master.hpp:641] Adding task 0 with resources
cpus(*):1; mem(*):256 on slave 20140527-183949-143311683-39317-22750-0
(minerva.apache.org)
I0527 18:39:49.543187 22776 master.cpp:3021] Launching task 0 of framework
20140527-183949-143311683-39317-22750-0000 with resources cpus(*):1; mem(*):256
on slave 20140527-183949-143311683-39317-22750-0 at
slave(62)@67.195.138.8:39317 (minerva.apache.org)
I0527 18:39:49.543287 22773 slave.cpp:934] Got assigned task 0 for framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.543428 22775 hierarchical_allocator_process.hpp:546] Framework
20140527-183949-143311683-39317-22750-0000 left cpus(*):2; mem(*):768;
disk(*):23038; ports(*):[31000-32000] unused on slave
20140527-183949-143311683-39317-22750-0
I0527 18:39:49.543495 22773 slave.cpp:1044] Launching task 0 for framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.545410 22773 exec.cpp:131] Version: 0.19.0
I0527 18:39:49.545459 22772 exec.cpp:181] Executor started at:
executor(29)@67.195.138.8:39317 with pid 22750
I0527 18:39:49.545531 22773 slave.cpp:1154] Queuing task '0' for executor
default of framework '20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.545579 22773 slave.cpp:497] Successfully attached file
'/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default/runs/1f93b8fc-f8ef-4d26-ad43-37df885fc912'
I0527 18:39:49.545601 22773 slave.cpp:1634] Got registration for executor
'default' of framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.545675 22773 slave.cpp:1753] Flushing queued task 0 for executor
'default' of framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.545691 22772 exec.cpp:205] Executor registered on slave
20140527-183949-143311683-39317-22750-0
I0527 18:39:49.545721 22773 slave.cpp:2325] Monitoring executor 'default' of
framework '20140527-183949-143311683-39317-22750-0000' in container
'1f93b8fc-f8ef-4d26-ad43-37df885fc912'
I0527 18:39:49.546452 22772 exec.cpp:217] Executor::registered took 10956ns
I0527 18:39:49.546490 22772 exec.cpp:292] Executor asked to run task '0'
I0527 18:39:49.546514 22772 exec.cpp:301] Executor::launchTask took 14802ns
I0527 18:39:49.546789 22776 sched.cpp:725] Stopping framework
'20140527-183949-143311683-39317-22750-0000'
I0527 18:39:49.546938 22776 master.cpp:655] Framework
20140527-183949-143311683-39317-22750-0000 disconnected
I0527 18:39:49.546951 22776 master.cpp:1298] Deactivating framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.546977 22776 master.cpp:677] Giving framework
20140527-183949-143311683-39317-22750-0000 100ms to failover
I0527 18:39:49.547056 22776 hierarchical_allocator_process.hpp:407] Deactivated
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.548360 22750 sched.cpp:121] Version: 0.19.0
I0527 18:39:49.548619 22772 sched.cpp:217] New master detected at
[email protected]:39317
I0527 18:39:49.548635 22772 sched.cpp:268] Authenticating with master
[email protected]:39317
I0527 18:39:49.548727 22771 authenticatee.hpp:128] Creating new client SASL
connection
I0527 18:39:49.548872 22770 master.cpp:2896] Authenticating
scheduler(60)@67.195.138.8:39317
I0527 18:39:49.548933 22771 authenticator.hpp:156] Creating new server SASL
connection
I0527 18:39:49.549048 22772 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0527 18:39:49.549067 22772 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0527 18:39:49.549106 22772 authenticator.hpp:262] Received SASL authentication
start
I0527 18:39:49.549157 22772 authenticator.hpp:384] Authentication requires more
steps
I0527 18:39:49.549191 22772 authenticatee.hpp:265] Received SASL authentication
step
I0527 18:39:49.549237 22772 authenticator.hpp:290] Received SASL authentication
step
I0527 18:39:49.549254 22772 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0527 18:39:49.647959 22773 master.cpp:2759] Framework failover timeout,
removing framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.794754 22772 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0527 18:39:49.794769 22773 master.cpp:3254] Removing framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.794778 22772 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0527 18:39:49.794790 22772 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'minerva.apache.org' server FQDN:
'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0527 18:39:49.794800 22772 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.794806 22772 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0527 18:39:49.794824 22772 authenticator.hpp:376] Authentication success
I0527 18:39:49.794836 22774 slave.cpp:1338] Asked to shut down framework
20140527-183949-143311683-39317-22750-0000 by [email protected]:39317
I0527 18:39:49.794853 22772 authenticatee.hpp:305] Authentication success
I0527 18:39:49.794854 22774 slave.cpp:1363] Shutting down framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.794834 22773 master.hpp:659] Removing task 0 with resources
cpus(*):1; mem(*):256 on slave 20140527-183949-143311683-39317-22750-0
(minerva.apache.org)
I0527 18:39:49.794884 22774 slave.cpp:2668] Shutting down executor 'default' of
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.794922 22772 sched.cpp:342] Successfully authenticated with
master [email protected]:39317
I0527 18:39:49.794935 22772 sched.cpp:461] Sending registration request to
[email protected]:39317
I0527 18:39:49.794952 22770 exec.cpp:378] Executor asked to shutdown
W0527 18:39:49.794955 22773 master.cpp:3668] Removing task 0 of framework
20140527-183949-143311683-39317-22750-0000 and slave
20140527-183949-143311683-39317-22750-0 in non-terminal state TASK_STAGING
GMOCK WARNING:
Uninteresting mock function call - returning directly.
Function call: shutdown(0x2b6ac80506b0)
Stack trace:
I0527 18:39:49.795006 22770 exec.cpp:393] Executor::shutdown took 29189ns
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
../../src/tests/mesos.hpp:504:
Function call: resourcesRecovered(@0x2b6ac8049fc8
20140527-183949-143311683-39317-22750-0000, @0x2b6ac8049fa8
20140527-183949-143311683-39317-22750-0, @0x2b6ac8049f90 { cpus(*):1,
mem(*):256 })
Stack trace:
I0527 18:39:49.795085 22773 master.cpp:2936] Successfully authenticated
principal 'test-principal' at scheduler(60)@67.195.138.8:39317
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
../../src/tests/mesos.hpp:504:
Function call: resourcesRecovered(@0x2b6ac805afb8
20140527-183949-143311683-39317-22750-0000, @0x2b6ac805af98
20140527-183949-143311683-39317-22750-0, @0x2b6ac805af80 {})
IStack trace:
0527 18:39:49.795105 22770 hierarchical_allocator_process.hpp:636] Recovered
cpus(*):1; mem(*):256 (total allocatable: cpus(*):3; mem(*):1024;
disk(*):23038; ports(*):[31000-32000]) on slave
20140527-183949-143311683-39317-22750-0 from framework
20140527-183949-143311683-39317-22750-0000
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
../../src/tests/mesos.hpp:474:
Function call: frameworkRemoved(@0x2b6ac8042590
20140527-183949-143311683-39317-22750-0000)
Stack trace:
I0527 18:39:49.795217 22770 hierarchical_allocator_process.hpp:362] Removed
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.795228 22773 master.cpp:1121] Re-registering framework
20140527-183949-143311683-39317-22750-0000 at scheduler(60)@67.195.138.8:39317
I0527 18:39:49.795326 22775 sched.cpp:392] Framework registered with
20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.795390 22775 sched.cpp:406] Scheduler::registered took 43876ns
W0527 18:39:49.795428 22773 slave.cpp:1511] Ignoring updating pid for framework
20140527-183949-143311683-39317-22750-0000 because it is terminating
I0527 18:39:49.795480 22773 hierarchical_allocator_process.hpp:331] Added
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:49.795516 22773 hierarchical_allocator_process.hpp:751] Offering
cpus(*):3; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave
20140527-183949-143311683-39317-22750-0 to framework
20140527-183949-143311683-39317-22750-0000
../../src/tests/allocator_tests.cpp:985: Failure
Mock function called more times than expected - taking default action specified
at:
../../src/tests/mesos.hpp:471:
Function call: frameworkAdded(@0x2b6ac8049fd0
20140527-183949-143311683-39317-22750-0000, @0x2b6ac8049f78 88-byte object
<50-FA 30-B9 6A-2B 00-00 00-00 00-00 00-00 00-00 C0-F2 04-C8 6A-2B 00-00 00-F3
04-C8 6A-2B 00-00 20-F3 04-C8 6A-2B 00-00 00-00 00-00 00-00 00-00 F0-27 AD-01
00-00 00-00 70-F2 04-C8 6A-2B 00-00 50-F2 04-C8 6A-2B 00-00 00-6E 28-29 00-00
00-00 C7-00 00-00 65-64 20-2D>, @0x2b6ac8049f60 {})
Expected: to be called once
Actual: called twice - over-saturated and active
I0527 18:39:49.795651 22773 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 160958ns
I0527 18:39:49.795694 22772 master.hpp:669] Adding offer
20140527-183949-143311683-39317-22750-1 with resources cpus(*):3; mem(*):1024;
disk(*):23038; ports(*):[31000-32000] on slave
20140527-183949-143311683-39317-22750-0 (minerva.apache.org)
I0527 18:39:49.795737 22772 master.cpp:2843] Sending 1 offers to framework
20140527-183949-143311683-39317-22750-0000
unknown file: Failure
Unexpected mock function call - returning directly.
Function call: resourceOffers(0x7fffd0fff860, @0x2b6abb7b1c70 { 128-byte
object <50-09 31-B9 6A-2B 00-00 00-00 00-00 00-00 00-00 E0-B4 03-D8 6A-2B 00-00
80-B5 03-D8 6A-2B 00-00 20-B6 03-D8 6A-2B 00-00 10-74 04-D8 6A-2B 00-00 E0-5B
04-D8 6A-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 2D-31 12-2C 00-00 00-00
00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 33-33 31-31 00-00 00-00 00-00
00-00 00-00 00-00 00-00 00-00 00-00 00-00 1A-29 0A-27 00-00 00-00 0F-00 00-00>
})
Google Mock tried the following 1 expectation, but it didn't match:
../../src/tests/allocator_tests.cpp:1053: EXPECT_CALL(sched2, resourceOffers(_,
OfferEq(2, 768)))...
Expected arg #1: contains 2 cpus and 768 mem
Actual: { 128-byte object <50-09 31-B9 6A-2B 00-00 00-00 00-00 00-00
00-00 E0-B4 03-D8 6A-2B 00-00 80-B5 03-D8 6A-2B 00-00 20-B6 03-D8 6A-2B 00-00
10-74 04-D8 6A-2B 00-00 E0-5B 04-D8 6A-2B 00-00 04-00 00-00 04-00 00-00 04-00
00-00 2D-31 12-2C 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00
33-33 31-31 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 1A-29
0A-27 00-00 00-00 0F-00 00-00> }, 3 cpus and 1024mem
Expected: to be called once
Actual: never called - unsatisfied and active
I0527 18:39:49.796044 22772 sched.cpp:529] Scheduler::resourceOffers took
226830ns
I0527 18:39:50.037924 22776 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 25463ns
I0527 18:39:51.038499 22774 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 13007ns
I0527 18:39:52.038606 22772 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 20094ns
I0527 18:39:53.039710 22773 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 13711ns
I0527 18:39:54.037348 22771 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0527 18:39:54.040472 22775 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 14624ns
I0527 18:39:54.795531 22774 slave.cpp:2738] Killing executor 'default' of
framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:54.795672 22774 slave.cpp:2383] Executor 'default' of framework
20140527-183949-143311683-39317-22750-0000 has exited with status 0
I0527 18:39:54.795761 22774 slave.cpp:2522] Cleaning up executor 'default' of
framework 20140527-183949-143311683-39317-22750-0000
W0527 18:39:54.795871 22770 master.cpp:2628] Ignoring unknown exited executor
default on slave 20140527-183949-143311683-39317-22750-0 at
slave(62)@67.195.138.8:39317 (minerva.apache.org)
I0527 18:39:54.796061 22774 slave.cpp:2597] Cleaning up framework
20140527-183949-143311683-39317-22750-0000
I0527 18:39:54.796068 22771 gc.cpp:56] Scheduling
'/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default/runs/1f93b8fc-f8ef-4d26-ad43-37df885fc912'
for gc 6.99999078708444days in the future
I0527 18:39:54.796128 22776 status_update_manager.cpp:282] Closing status
update streams for framework 20140527-183949-143311683-39317-22750-0000
I0527 18:39:54.796171 22771 gc.cpp:56] Scheduling
'/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000/executors/default'
for gc 6.9999907865037days in the future
I0527 18:39:54.796210 22771 gc.cpp:56] Scheduling
'/tmp/AllocatorTest_0_SchedulerFailover_MYos5v/slaves/20140527-183949-143311683-39317-22750-0/frameworks/20140527-183949-143311683-39317-22750-0000'
for gc 6.99999078577481days in the future
I0527 18:39:55.041219 22776 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 28557ns
I0527 18:39:56.041731 22777 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 10760ns
I0527 18:39:57.042177 22772 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 9990ns
I0527 18:39:58.042736 22771 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 9554ns
I0527 18:39:59.038238 22775 master.cpp:108] No whitelist given. Advertising
offers for all slaves
I0527 18:39:59.043576 22773 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 47160ns
../../src/tests/allocator_tests.cpp:1058: Failure
Failed to wait 10secs for resourceOffers
I0527 18:40:00.043962 22775 hierarchical_allocator_process.hpp:687] Performed
allocation for 1 slaves in 14603ns
--
This message was sent by Atlassian JIRA
(v6.2#6252)
