You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Liqiang Lin (JIRA)" <ji...@apache.org> on 2015/10/14 08:21:06 UTC
[jira] [Commented] (MESOS-1848)
DRFAllocatorTest.DRFAllocatorProcess is flaky
[ https://issues.apache.org/jira/browse/MESOS-1848?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14956344#comment-14956344 ]
Liqiang Lin commented on MESOS-1848:
------------------------------------
I's like to take this JIRA. But I can not reproduce this bug in my OSX machine.
> 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
> Labels: flaky
>
> 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 : master@192.168.122.164:47295
> I0929 20:11:12.813006 17017 master.cpp:1241] The newly elected leader is master@192.168.122.164: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 master@192.168.122.164:47295
> I0929 20:11:12.853714 17016 slave.cpp:672] Authenticating with master master@192.168.122.164:47295
> I0929 20:11:12.853927 17013 status_update_manager.cpp:167] New master detected at master@192.168.122.164: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 master@192.168.122.164:47295
> I0929 20:11:12.858435 17015 sched.cpp:283] Authenticating with master master@192.168.122.164: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 master@192.168.122.164: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 master@192.168.122.164: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] master@192.168.122.164: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 : master@192.168.122.164:47295
> I0929 20:11:12.813006 17017 master.cpp:1241] The newly elected leader is master@192.168.122.164: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 master@192.168.122.164:47295
> I0929 20:11:12.853714 17016 slave.cpp:672] Authenticating with master master@192.168.122.164:47295
> I0929 20:11:12.853927 17013 status_update_manager.cpp:167] New master detected at master@192.168.122.164: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 master@192.168.122.164:47295
> I0929 20:11:12.858435 17015 sched.cpp:283] Authenticating with master master@192.168.122.164: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 master@192.168.122.164: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 master@192.168.122.164: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] master@192.168.122.164: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)