Vinod Kone created MESOS-1848:
---------------------------------
Summary: DRFAllocatorTest.DRFAllocatorProcess is flaky
Key: MESOS-1848
URL: https://issues.apache.org/jira/browse/MESOS-1848
Project: Mesos
Issue Type: Bug
Components: test
Environment: Fedora 20
Reporter: Vinod Kone
Observed this on CI. This is pretty strange because the authentication of both
the framework and slave timed out at the very beginning, even though we don't
manipulate clocks.
{code}
[ RUN ] DRFAllocatorTest.DRFAllocatorProcess
Using temporary directory '/tmp/DRFAllocatorTest_DRFAllocatorProcess_igiR9X'
I0929 20:11:12.801327 16997 leveldb.cpp:176] Opened db in 489720ns
I0929 20:11:12.801627 16997 leveldb.cpp:183] Compacted db in 168280ns
I0929 20:11:12.801784 16997 leveldb.cpp:198] Created db iterator in 5820ns
I0929 20:11:12.801898 16997 leveldb.cpp:204] Seeked to beginning of db in 1285ns
I0929 20:11:12.802039 16997 leveldb.cpp:273] Iterated through 0 keys in the db
in 792ns
I0929 20:11:12.802160 16997 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0929 20:11:12.802441 17012 recover.cpp:425] Starting replica recovery
I0929 20:11:12.802623 17012 recover.cpp:451] Replica is in EMPTY status
I0929 20:11:12.803251 17012 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0929 20:11:12.803427 17012 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0929 20:11:12.803632 17012 recover.cpp:542] Updating replica status to STARTING
I0929 20:11:12.803911 17012 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 33999ns
I0929 20:11:12.804033 17012 replica.cpp:320] Persisted replica status to
STARTING
I0929 20:11:12.804245 17012 recover.cpp:451] Replica is in STARTING status
I0929 20:11:12.804592 17012 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0929 20:11:12.804775 17012 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0929 20:11:12.804952 17012 recover.cpp:542] Updating replica status to VOTING
I0929 20:11:12.805115 17012 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 15990ns
I0929 20:11:12.805234 17012 replica.cpp:320] Persisted replica status to VOTING
I0929 20:11:12.805366 17012 recover.cpp:556] Successfully joined the Paxos group
I0929 20:11:12.805539 17012 recover.cpp:440] Recover process terminated
I0929 20:11:12.809062 17017 master.cpp:312] Master
20140929-201112-2759502016-47295-16997 (fedora-20) started on
192.168.122.164:47295
I0929 20:11:12.809432 17017 master.cpp:358] Master only allowing authenticated
frameworks to register
I0929 20:11:12.809546 17017 master.cpp:363] Master only allowing authenticated
slaves to register
I0929 20:11:12.810169 17017 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_igiR9X/credentials'
I0929 20:11:12.810510 17017 master.cpp:392] Authorization enabled
I0929 20:11:12.811841 17016 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:12.812099 17013 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master :
[email protected]:47295
I0929 20:11:12.813006 17017 master.cpp:1241] The newly elected leader is
[email protected]:47295 with id 20140929-201112-2759502016-47295-16997
I0929 20:11:12.813164 17017 master.cpp:1254] Elected as the leading master!
I0929 20:11:12.813279 17017 master.cpp:1072] Recovering from registrar
I0929 20:11:12.813487 17013 registrar.cpp:312] Recovering registrar
I0929 20:11:12.813824 17013 log.cpp:656] Attempting to start the writer
I0929 20:11:12.814256 17013 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0929 20:11:12.814419 17013 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 25049ns
I0929 20:11:12.814581 17013 replica.cpp:342] Persisted promised to 1
I0929 20:11:12.814909 17013 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0929 20:11:12.815340 17013 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0929 20:11:12.815497 17013 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 19855ns
I0929 20:11:12.815636 17013 replica.cpp:676] Persisted action at 0
I0929 20:11:12.816066 17013 replica.cpp:508] Replica received write request for
position 0
I0929 20:11:12.816220 17013 leveldb.cpp:438] Reading position from leveldb took
15731ns
I0929 20:11:12.816356 17013 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 17814ns
I0929 20:11:12.816488 17013 replica.cpp:676] Persisted action at 0
I0929 20:11:12.820883 17012 replica.cpp:655] Replica received learned notice
for position 0
I0929 20:11:12.821038 17012 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 22047ns
I0929 20:11:12.821261 17012 replica.cpp:676] Persisted action at 0
I0929 20:11:12.821374 17012 replica.cpp:661] Replica learned NOP action at
position 0
I0929 20:11:12.821724 17012 log.cpp:672] Writer started with ending position 0
I0929 20:11:12.822145 17012 leveldb.cpp:438] Reading position from leveldb took
13843ns
I0929 20:11:12.823463 17012 registrar.cpp:345] Successfully fetched the
registry (0B)
I0929 20:11:12.823686 17012 registrar.cpp:421] Attempting to update the
'registry'
I0929 20:11:12.824872 17011 log.cpp:680] Attempting to append 131 bytes to the
log
I0929 20:11:12.825119 17011 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0929 20:11:12.825507 17011 replica.cpp:508] Replica received write request for
position 1
I0929 20:11:12.825734 17011 leveldb.cpp:343] Persisting action (150 bytes) to
leveldb took 22771ns
I0929 20:11:12.825917 17011 replica.cpp:676] Persisted action at 1
I0929 20:11:12.827862 17016 replica.cpp:655] Replica received learned notice
for position 1
I0929 20:11:12.828042 17016 leveldb.cpp:343] Persisting action (152 bytes) to
leveldb took 27499ns
I0929 20:11:12.828163 17016 replica.cpp:676] Persisted action at 1
I0929 20:11:12.828304 17016 replica.cpp:661] Replica learned APPEND action at
position 1
I0929 20:11:12.828604 17016 log.cpp:699] Attempting to truncate the log to 1
I0929 20:11:12.828783 17016 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0929 20:11:12.829092 17016 replica.cpp:508] Replica received write request for
position 2
I0929 20:11:12.829241 17016 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 24041ns
I0929 20:11:12.829370 17016 replica.cpp:676] Persisted action at 2
I0929 20:11:12.829731 17016 replica.cpp:655] Replica received learned notice
for position 2
I0929 20:11:12.829942 17016 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 41634ns
I0929 20:11:12.830106 17016 leveldb.cpp:401] Deleting ~1 keys from leveldb took
17781ns
I0929 20:11:12.830235 17016 replica.cpp:676] Persisted action at 2
I0929 20:11:12.830405 17016 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0929 20:11:12.833751 17012 registrar.cpp:478] Successfully updated 'registry'
I0929 20:11:12.833909 17012 registrar.cpp:371] Successfully recovered registrar
I0929 20:11:12.834215 17018 master.cpp:1099] Recovered 0 slaves from the
Registry (95B) ; allowing 10mins for slaves to re-register
I0929 20:11:12.845304 16997 containerizer.cpp:89] Using isolation:
posix/cpu,posix/mem
I0929 20:11:12.849077 17017 slave.cpp:169] Slave started on
1)@192.168.122.164:47295
I0929 20:11:12.849483 17017 credentials.hpp:84] Loading credential for
authentication from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_JKh7ij/credential'
I0929 20:11:12.849735 17017 slave.cpp:276] Slave using credential for:
test-principal
I0929 20:11:12.850129 17017 slave.cpp:289] Slave resources: cpus(*):2;
mem(*):1024; disk(*):0; ports(*):[31000-32000]
I0929 20:11:12.850781 17017 slave.cpp:317] Slave hostname: fedora-20
I0929 20:11:12.850920 17017 slave.cpp:318] Slave checkpoint: false
I0929 20:11:12.851788 17016 state.cpp:33] Recovering state from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_JKh7ij/meta'
I0929 20:11:12.852089 17016 status_update_manager.cpp:193] Recovering status
update manager
I0929 20:11:12.852355 17016 containerizer.cpp:252] Recovering containerizer
I0929 20:11:12.852949 17016 slave.cpp:3271] Finished recovery
I0929 20:11:12.853415 17016 slave.cpp:598] New master detected at
[email protected]:47295
I0929 20:11:12.853714 17016 slave.cpp:672] Authenticating with master
[email protected]:47295
I0929 20:11:12.853927 17013 status_update_manager.cpp:167] New master detected
at [email protected]:47295
I0929 20:11:12.854290 17018 authenticatee.hpp:104] Initializing client SASL
I0929 20:11:12.854616 17016 slave.cpp:645] Detecting new master
I0929 20:11:12.857573 16997 sched.cpp:137] Version: 0.21.0
I0929 20:11:12.857925 17015 sched.cpp:233] New master detected at
[email protected]:47295
I0929 20:11:12.858435 17015 sched.cpp:283] Authenticating with master
[email protected]:47295
I0929 20:11:12.988668 17018 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:12.989294 17015 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:13.813364 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:13.813910 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 559406ns
I0929 20:11:14.814724 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:14.815001 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 279683ns
I0929 20:11:15.816067 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:15.816335 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 277524ns
I0929 20:11:16.816997 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:16.817261 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 316868ns
I0929 20:11:17.812933 17014 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:17.818584 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:17.818758 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 174122ns
W0929 20:11:17.855309 17011 slave.cpp:746] Authentication timed out
W0929 20:11:17.858809 17014 sched.cpp:378] Authentication timed out
I0929 20:11:18.819345 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:18.819602 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 261229ns
I0929 20:11:19.820294 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:19.820873 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 590879ns
I0929 20:11:20.821741 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:20.822089 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 354741ns
I0929 20:11:21.823289 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:21.823717 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 451454ns
I0929 20:11:22.814144 17014 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:22.823961 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:22.824234 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 277050ns
tests/allocator_tests.cpp:120: Failure
Failed to wait 10secs for offers1
I0929 20:11:23.825175 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:23.825216 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 48326ns
W0929 20:11:24.783859 17015 slave.cpp:710] Failed to authenticate with master
[email protected]:47295: Authentication discarded
tests/allocator_tests.cpp:115: Failure
Actual function call count doesn't match EXPECT_CALL(sched1, resourceOffers(_,
_))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/allocator_tests.cpp:112: Failure
Actual function call count doesn't match EXPECT_CALL(sched1, registered(_, _,
_))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0929 20:11:24.784392 17015 slave.cpp:672] Authenticating with master
[email protected]:47295
tests/allocator_tests.cpp:94: Failure
Actual function call count doesn't match EXPECT_CALL(allocator, slaveAdded(_,
_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/allocator_tests.cpp:110: Failure
Actual function call count doesn't match EXPECT_CALL(allocator,
frameworkAdded(_, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0929 20:11:24.785089 17015 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:24.785411 17018 master.cpp:3737] Authenticating
slave(1)@192.168.122.164:47295
I0929 20:11:24.785806 17017 authenticator.hpp:94] Initializing server SASL
I0929 20:11:24.786264 17018 master.cpp:676] Master terminating
I0929 20:11:24.788043 17017 auxprop.cpp:45] Initialized in-memory auxiliary
property plugin
I0929 20:11:24.793727 17018 slave.cpp:2430] [email protected]:47295 exited
W0929 20:11:24.795372 17018 slave.cpp:2433] Master disconnected! Waiting for a
new master to be elected
*** Aborted at 1412046684 (unix time) try "date -d @1412046684" if you are
using GNU date ***
PC: @ 0x7f78d32e54a8 (unknown)
*** SIGSEGV (@0x7fffb4556d18) received by PID 16997 (TID 0x7f78d5c32880) from
PID 18446744072440081688; stack trace: ***
@ 0x7f78d3de3720 (unknown)
@ 0x7f78d32e54a8 (unknown)
@ 0x4bf626
mesos::internal::master::allocator::Allocator::~Allocator()
@ 0x7b24a0 std::_Sp_counted_ptr<>::_M_dispose()
@ 0x4ce6b9 std::_Sp_counted_base<>::_M_release()
@ 0x4ce7d8
mesos::internal::tests::Cluster::Masters::Master::~Master()
@ 0x4d1154 std::_Rb_tree<>::_M_erase()
@ 0x4fc43b mesos::internal::tests::Cluster::Masters::shutdown()
@ 0x7ac13d mesos::internal::tests::MesosTest::Shutdown()
@ 0x99ed33
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x995fc0 testing::Test::Run()
@ 0x99609e testing::TestInfo::Run()
@ 0x9961a5 testing::TestCase::Run()
@ 0x996448 testing::internal::UnitTestImpl::RunAllTests()
@ 0x9966d7 testing::UnitTest::Run()
@ 0x49513b main
@ 0x7f78d296cd65 __libc_start_main
@ 0x4a4089 (unknown)
make[3]: *** [check-local] Segmentation fault (core dumped)
[ RUN ] DRFAllocatorTest.DRFAllocatorProcess
Using temporary directory '/tmp/DRFAllocatorTest_DRFAllocatorProcess_igiR9X'
I0929 20:11:12.801327 16997 leveldb.cpp:176] Opened db in 489720ns
I0929 20:11:12.801627 16997 leveldb.cpp:183] Compacted db in 168280ns
I0929 20:11:12.801784 16997 leveldb.cpp:198] Created db iterator in 5820ns
I0929 20:11:12.801898 16997 leveldb.cpp:204] Seeked to beginning of db in 1285ns
I0929 20:11:12.802039 16997 leveldb.cpp:273] Iterated through 0 keys in the db
in 792ns
I0929 20:11:12.802160 16997 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0929 20:11:12.802441 17012 recover.cpp:425] Starting replica recovery
I0929 20:11:12.802623 17012 recover.cpp:451] Replica is in EMPTY status
I0929 20:11:12.803251 17012 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0929 20:11:12.803427 17012 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0929 20:11:12.803632 17012 recover.cpp:542] Updating replica status to STARTING
I0929 20:11:12.803911 17012 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 33999ns
I0929 20:11:12.804033 17012 replica.cpp:320] Persisted replica status to
STARTING
I0929 20:11:12.804245 17012 recover.cpp:451] Replica is in STARTING status
I0929 20:11:12.804592 17012 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0929 20:11:12.804775 17012 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0929 20:11:12.804952 17012 recover.cpp:542] Updating replica status to VOTING
I0929 20:11:12.805115 17012 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 15990ns
I0929 20:11:12.805234 17012 replica.cpp:320] Persisted replica status to VOTING
I0929 20:11:12.805366 17012 recover.cpp:556] Successfully joined the Paxos group
I0929 20:11:12.805539 17012 recover.cpp:440] Recover process terminated
I0929 20:11:12.809062 17017 master.cpp:312] Master
20140929-201112-2759502016-47295-16997 (fedora-20) started on
192.168.122.164:47295
I0929 20:11:12.809432 17017 master.cpp:358] Master only allowing authenticated
frameworks to register
I0929 20:11:12.809546 17017 master.cpp:363] Master only allowing authenticated
slaves to register
I0929 20:11:12.810169 17017 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_igiR9X/credentials'
I0929 20:11:12.810510 17017 master.cpp:392] Authorization enabled
I0929 20:11:12.811841 17016 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:12.812099 17013 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master :
[email protected]:47295
I0929 20:11:12.813006 17017 master.cpp:1241] The newly elected leader is
[email protected]:47295 with id 20140929-201112-2759502016-47295-16997
I0929 20:11:12.813164 17017 master.cpp:1254] Elected as the leading master!
I0929 20:11:12.813279 17017 master.cpp:1072] Recovering from registrar
I0929 20:11:12.813487 17013 registrar.cpp:312] Recovering registrar
I0929 20:11:12.813824 17013 log.cpp:656] Attempting to start the writer
I0929 20:11:12.814256 17013 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0929 20:11:12.814419 17013 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 25049ns
I0929 20:11:12.814581 17013 replica.cpp:342] Persisted promised to 1
I0929 20:11:12.814909 17013 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0929 20:11:12.815340 17013 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0929 20:11:12.815497 17013 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 19855ns
I0929 20:11:12.815636 17013 replica.cpp:676] Persisted action at 0
I0929 20:11:12.816066 17013 replica.cpp:508] Replica received write request for
position 0
I0929 20:11:12.816220 17013 leveldb.cpp:438] Reading position from leveldb took
15731ns
I0929 20:11:12.816356 17013 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 17814ns
I0929 20:11:12.816488 17013 replica.cpp:676] Persisted action at 0
I0929 20:11:12.820883 17012 replica.cpp:655] Replica received learned notice
for position 0
I0929 20:11:12.821038 17012 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 22047ns
I0929 20:11:12.821261 17012 replica.cpp:676] Persisted action at 0
I0929 20:11:12.821374 17012 replica.cpp:661] Replica learned NOP action at
position 0
I0929 20:11:12.821724 17012 log.cpp:672] Writer started with ending position 0
I0929 20:11:12.822145 17012 leveldb.cpp:438] Reading position from leveldb took
13843ns
I0929 20:11:12.823463 17012 registrar.cpp:345] Successfully fetched the
registry (0B)
I0929 20:11:12.823686 17012 registrar.cpp:421] Attempting to update the
'registry'
I0929 20:11:12.824872 17011 log.cpp:680] Attempting to append 131 bytes to the
log
I0929 20:11:12.825119 17011 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0929 20:11:12.825507 17011 replica.cpp:508] Replica received write request for
position 1
I0929 20:11:12.825734 17011 leveldb.cpp:343] Persisting action (150 bytes) to
leveldb took 22771ns
I0929 20:11:12.825917 17011 replica.cpp:676] Persisted action at 1
I0929 20:11:12.827862 17016 replica.cpp:655] Replica received learned notice
for position 1
I0929 20:11:12.828042 17016 leveldb.cpp:343] Persisting action (152 bytes) to
leveldb took 27499ns
I0929 20:11:12.828163 17016 replica.cpp:676] Persisted action at 1
I0929 20:11:12.828304 17016 replica.cpp:661] Replica learned APPEND action at
position 1
I0929 20:11:12.828604 17016 log.cpp:699] Attempting to truncate the log to 1
I0929 20:11:12.828783 17016 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0929 20:11:12.829092 17016 replica.cpp:508] Replica received write request for
position 2
I0929 20:11:12.829241 17016 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 24041ns
I0929 20:11:12.829370 17016 replica.cpp:676] Persisted action at 2
I0929 20:11:12.829731 17016 replica.cpp:655] Replica received learned notice
for position 2
I0929 20:11:12.829942 17016 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 41634ns
I0929 20:11:12.830106 17016 leveldb.cpp:401] Deleting ~1 keys from leveldb took
17781ns
I0929 20:11:12.830235 17016 replica.cpp:676] Persisted action at 2
I0929 20:11:12.830405 17016 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0929 20:11:12.833751 17012 registrar.cpp:478] Successfully updated 'registry'
I0929 20:11:12.833909 17012 registrar.cpp:371] Successfully recovered registrar
I0929 20:11:12.834215 17018 master.cpp:1099] Recovered 0 slaves from the
Registry (95B) ; allowing 10mins for slaves to re-register
I0929 20:11:12.845304 16997 containerizer.cpp:89] Using isolation:
posix/cpu,posix/mem
I0929 20:11:12.849077 17017 slave.cpp:169] Slave started on
1)@192.168.122.164:47295
I0929 20:11:12.849483 17017 credentials.hpp:84] Loading credential for
authentication from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_JKh7ij/credential'
I0929 20:11:12.849735 17017 slave.cpp:276] Slave using credential for:
test-principal
I0929 20:11:12.850129 17017 slave.cpp:289] Slave resources: cpus(*):2;
mem(*):1024; disk(*):0; ports(*):[31000-32000]
I0929 20:11:12.850781 17017 slave.cpp:317] Slave hostname: fedora-20
I0929 20:11:12.850920 17017 slave.cpp:318] Slave checkpoint: false
I0929 20:11:12.851788 17016 state.cpp:33] Recovering state from
'/tmp/DRFAllocatorTest_DRFAllocatorProcess_JKh7ij/meta'
I0929 20:11:12.852089 17016 status_update_manager.cpp:193] Recovering status
update manager
I0929 20:11:12.852355 17016 containerizer.cpp:252] Recovering containerizer
I0929 20:11:12.852949 17016 slave.cpp:3271] Finished recovery
I0929 20:11:12.853415 17016 slave.cpp:598] New master detected at
[email protected]:47295
I0929 20:11:12.853714 17016 slave.cpp:672] Authenticating with master
[email protected]:47295
I0929 20:11:12.853927 17013 status_update_manager.cpp:167] New master detected
at [email protected]:47295
I0929 20:11:12.854290 17018 authenticatee.hpp:104] Initializing client SASL
I0929 20:11:12.854616 17016 slave.cpp:645] Detecting new master
I0929 20:11:12.857573 16997 sched.cpp:137] Version: 0.21.0
I0929 20:11:12.857925 17015 sched.cpp:233] New master detected at
[email protected]:47295
I0929 20:11:12.858435 17015 sched.cpp:283] Authenticating with master
[email protected]:47295
I0929 20:11:12.988668 17018 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:12.989294 17015 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:13.813364 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:13.813910 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 559406ns
I0929 20:11:14.814724 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:14.815001 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 279683ns
I0929 20:11:15.816067 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:15.816335 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 277524ns
I0929 20:11:16.816997 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:16.817261 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 316868ns
I0929 20:11:17.812933 17014 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:17.818584 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:17.818758 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 174122ns
W0929 20:11:17.855309 17011 slave.cpp:746] Authentication timed out
W0929 20:11:17.858809 17014 sched.cpp:378] Authentication timed out
I0929 20:11:18.819345 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:18.819602 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 261229ns
I0929 20:11:19.820294 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:19.820873 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 590879ns
I0929 20:11:20.821741 17011 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:20.822089 17011 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 354741ns
I0929 20:11:21.823289 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:21.823717 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 451454ns
I0929 20:11:22.814144 17014 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0929 20:11:22.823961 17017 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:22.824234 17017 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 277050ns
tests/allocator_tests.cpp:120: Failure
Failed to wait 10secs for offers1
I0929 20:11:23.825175 17012 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0929 20:11:23.825216 17012 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 48326ns
W0929 20:11:24.783859 17015 slave.cpp:710] Failed to authenticate with master
[email protected]:47295: Authentication discarded
tests/allocator_tests.cpp:115: Failure
Actual function call count doesn't match EXPECT_CALL(sched1, resourceOffers(_,
_))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/allocator_tests.cpp:112: Failure
Actual function call count doesn't match EXPECT_CALL(sched1, registered(_, _,
_))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0929 20:11:24.784392 17015 slave.cpp:672] Authenticating with master
[email protected]:47295
tests/allocator_tests.cpp:94: Failure
Actual function call count doesn't match EXPECT_CALL(allocator, slaveAdded(_,
_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/allocator_tests.cpp:110: Failure
Actual function call count doesn't match EXPECT_CALL(allocator,
frameworkAdded(_, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0929 20:11:24.785089 17015 authenticatee.hpp:128] Creating new client SASL
connection
I0929 20:11:24.785411 17018 master.cpp:3737] Authenticating
slave(1)@192.168.122.164:47295
I0929 20:11:24.785806 17017 authenticator.hpp:94] Initializing server SASL
I0929 20:11:24.786264 17018 master.cpp:676] Master terminating
I0929 20:11:24.788043 17017 auxprop.cpp:45] Initialized in-memory auxiliary
property plugin
I0929 20:11:24.793727 17018 slave.cpp:2430] [email protected]:47295 exited
W0929 20:11:24.795372 17018 slave.cpp:2433] Master disconnected! Waiting for a
new master to be elected
*** Aborted at 1412046684 (unix time) try "date -d @1412046684" if you are
using GNU date ***
PC: @ 0x7f78d32e54a8 (unknown)
*** SIGSEGV (@0x7fffb4556d18) received by PID 16997 (TID 0x7f78d5c32880) from
PID 18446744072440081688; stack trace: ***
@ 0x7f78d3de3720 (unknown)
@ 0x7f78d32e54a8 (unknown)
@ 0x4bf626
mesos::internal::master::allocator::Allocator::~Allocator()
@ 0x7b24a0 std::_Sp_counted_ptr<>::_M_dispose()
@ 0x4ce6b9 std::_Sp_counted_base<>::_M_release()
@ 0x4ce7d8
mesos::internal::tests::Cluster::Masters::Master::~Master()
@ 0x4d1154 std::_Rb_tree<>::_M_erase()
@ 0x4fc43b mesos::internal::tests::Cluster::Masters::shutdown()
@ 0x7ac13d mesos::internal::tests::MesosTest::Shutdown()
@ 0x99ed33
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x995fc0 testing::Test::Run()
@ 0x99609e testing::TestInfo::Run()
@ 0x9961a5 testing::TestCase::Run()
@ 0x996448 testing::internal::UnitTestImpl::RunAllTests()
@ 0x9966d7 testing::UnitTest::Run()
@ 0x49513b main
@ 0x7f78d296cd65 __libc_start_main
@ 0x4a4089 (unknown)
make[3]: *** [check-local] Segmentation fault (core dumped)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
