Looks like there was a complete stall in the test, based on the logging
timestamps. Also note the out-of-order timestamps:
1022 *23:49:59*.147037 28617 slave.cpp:2197] Handling status update
TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0
of framework 20141022-234958-3142697795-36297-28588-0000 from
executor(34)@67.195.81.187:36297
I1022 *23:49:59*.147059 28617 slave.cpp:4160] Terminating task 0
I../../src/tests/reconciliation_tests.cpp:720: Failure
Failed to wait 10secs for update1
../../src/tests/reconciliation_tests.cpp:703: Failure
Actual function call count doesn't match EXPECT_CALL(sched,
statusUpdate(&driver, _))...
Expected: to be called once
1022 *23:49:59*.147155 28617 status_update_manager.cpp:317] Received
status update TASK_FINISHED (UUID:
9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework
20141022-234958-3142697795-36297-28588-0000
Actual: never called - unsatisfied and active
I1022 *23:50:09*.380831 28617 status_update_manager.cpp:494] Creating
StatusUpdate stream for task 0 of framework
20141022-234958-3142697795-36297-28588-0000
I1022 *23:50:03*.785439 28613 master.cpp:120] No whitelist given.
Advertising offers for all slaves
I1022 *23:50:09*.380949 28617 status_update_manager.cpp:371]
Forwarding update TASK_FINISHED (UUID:
9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework
20141022-234958-3142697795-36297-28588-0000 to the slave
I1022 *23:50:09*.380975 28606 master.cpp:768] Framework
20141022-234958-3142697795-36297-28588-0000 (default) at
[email protected]:36297
disconnected
I1022 *23:49:59*.785217 28602 hierarchical_allocator_process.hpp:816]
Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]
on slave 20141022-234958-3142697795-36297-28588-S0 for framework
20141022-234958-3142697795-36297-28588-0000
I1022 *23:50:09*.380996 28606 master.cpp:1731] Disconnecting framework
20141022-234958-3142697795-36297-28588-0000 (default) at
[email protected]:36297
As for the pure virtual that results as part of the test failure, still
looking at it. Not clear how this can happen given the ResourceMonitor is
stored within the slave. Also not clear why the logging failure shows up
twice in the backtrace:
F1022 23:50:12.877830 28588 logging.cpp:57] RAW: Pure virtual method called
@ 0x2b89187e25dd google::LogMessage::Fail()
@ 0x2b89187e9cd6 google::RawLog__()
@ 0x2b89183f84d9
mesos::internal::slave::ResourceMonitorProcess::collect()
@ 0x2b89187a439a process::ProcessManager::resume()
@ 0x2b89187e25dd google::LogMessage::Fail()
@ 0x2b89187a465c process::schedule()
@ 0x2b89187e9cd6 google::RawLog__()
@ 0x507226 mesos::internal::tests::Cluster::Slaves::shutdown()
@ 0x7a7f24 mesos::internal::tests::MesosTest::ShutdownSlaves()
@ 0x9a4713
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x99b980 testing::Test::Run()
@ 0x99ba5e testing::TestInfo::Run()
@ 0x99bb65 testing::TestCase::Run()
@ 0x99be08 testing::internal::UnitTestImpl::RunAllTests()
@ 0x99c0a7 testing::UnitTest::Run()
@ 0x490aca main
@ 0x2b891a707ec5 (unknown)
@ 0x49dfa8 (unknown)
On Thu, Oct 23, 2014 at 11:15 AM, Benjamin Mahler <[email protected]
> wrote:
> Taking a look.
>
> On Wed, Oct 22, 2014 at 4:50 PM, Apache Jenkins Server <
> [email protected]> wrote:
>
>> See <
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2473/changes
>> >
>>
>> Changes:
>>
>> [dhamon] Differentiate between slave and offer ids
>>
>> ------------------------------------------
>> [...truncated 25823 lines...]
>> I1022 23:49:58.784020 28603 master.cpp:363] Master only allowing
>> authenticated slaves to register
>> I1022 23:49:58.784030 28603 credentials.hpp:36] Loading credentials for
>> authentication from
>> '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_VbLvU8/credentials'
>> I1022 23:49:58.784097 28608 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 1.060798ms
>> I1022 23:49:58.784119 28608 replica.cpp:320] Persisted replica status to
>> STARTING
>> I1022 23:49:58.784139 28603 master.cpp:392] Authorization enabled
>> I1022 23:49:58.784201 28608 recover.cpp:463] Replica is in STARTING status
>> I1022 23:49:58.784397 28608 master.cpp:120] No whitelist given.
>> Advertising offers for all slaves
>> I1022 23:49:58.784747 28611 hierarchical_allocator_process.hpp:299]
>> Initializing hierarchical allocator process with master :
>> [email protected]:36297
>> I1022 23:49:58.784898 28613 master.cpp:1242] The newly elected leader is
>> [email protected]:36297 with id 20141022-234958-3142697795-36297-28588
>> I1022 23:49:58.784914 28613 master.cpp:1255] Elected as the leading
>> master!
>> I1022 23:49:58.784924 28613 master.cpp:1073] Recovering from registrar
>> I1022 23:49:58.784926 28611 replica.cpp:638] Replica in STARTING status
>> received a broadcasted recover request
>> I1022 23:49:58.784993 28613 registrar.cpp:313] Recovering registrar
>> I1022 23:49:58.785223 28611 recover.cpp:188] Received a recover response
>> from a replica in STARTING status
>> I1022 23:49:58.785341 28611 recover.cpp:554] Updating replica status to
>> VOTING
>> I1022 23:49:58.785760 28611 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 333269ns
>> I1022 23:49:58.785778 28611 replica.cpp:320] Persisted replica status to
>> VOTING
>> I1022 23:49:58.785825 28611 recover.cpp:568] Successfully joined the
>> Paxos group
>> I1022 23:49:58.785892 28611 recover.cpp:452] Recover process terminated
>> I1022 23:49:58.786036 28611 log.cpp:656] Attempting to start the writer
>> I1022 23:49:58.786501 28606 replica.cpp:474] Replica received implicit
>> promise request with proposal 1
>> I1022 23:49:58.786792 28606 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 271018ns
>> I1022 23:49:58.786810 28606 replica.cpp:342] Persisted promised to 1
>> I1022 23:49:58.787049 28606 coordinator.cpp:230] Coordinator attemping to
>> fill missing position
>> I1022 23:49:58.787730 28610 replica.cpp:375] Replica received explicit
>> promise request for position 0 with proposal 2
>> I1022 23:49:58.788100 28610 leveldb.cpp:343] Persisting action (8 bytes)
>> to leveldb took 347683ns
>> I1022 23:49:58.788116 28610 replica.cpp:676] Persisted action at 0
>> I1022 23:49:58.788492 28610 replica.cpp:508] Replica received write
>> request for position 0
>> I1022 23:49:58.788524 28610 leveldb.cpp:438] Reading position from
>> leveldb took 16351ns
>> I1022 23:49:58.788832 28610 leveldb.cpp:343] Persisting action (14 bytes)
>> to leveldb took 288220ns
>> I1022 23:49:58.788848 28610 replica.cpp:676] Persisted action at 0
>> I1022 23:49:58.789029 28610 replica.cpp:655] Replica received learned
>> notice for position 0
>> I1022 23:49:58.789222 28610 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 176617ns
>> I1022 23:49:58.789238 28610 replica.cpp:676] Persisted action at 0
>> I1022 23:49:58.789247 28610 replica.cpp:661] Replica learned NOP action
>> at position 0
>> I1022 23:49:58.789477 28610 log.cpp:672] Writer started with ending
>> position 0
>> I1022 23:49:58.789831 28610 leveldb.cpp:438] Reading position from
>> leveldb took 11010ns
>> I1022 23:49:58.791254 28610 registrar.cpp:346] Successfully fetched the
>> registry (0B) in 6.239744ms
>> I1022 23:49:58.791309 28610 registrar.cpp:445] Applied 1 operations in
>> 4398ns; attempting to update the 'registry'
>> I1022 23:49:58.792754 28610 log.cpp:680] Attempting to append 139 bytes
>> to the log
>> I1022 23:49:58.792817 28610 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 1
>> I1022 23:49:58.793117 28610 replica.cpp:508] Replica received write
>> request for position 1
>> I1022 23:49:58.793505 28610 leveldb.cpp:343] Persisting action (158
>> bytes) to leveldb took 368961ns
>> I1022 23:49:58.793524 28610 replica.cpp:676] Persisted action at 1
>> I1022 23:49:58.793771 28610 replica.cpp:655] Replica received learned
>> notice for position 1
>> I1022 23:49:58.794075 28610 leveldb.cpp:343] Persisting action (160
>> bytes) to leveldb took 288311ns
>> I1022 23:49:58.794092 28610 replica.cpp:676] Persisted action at 1
>> I1022 23:49:58.794102 28610 replica.cpp:661] Replica learned APPEND
>> action at position 1
>> I1022 23:49:58.794467 28610 registrar.cpp:490] Successfully updated the
>> 'registry' in 3.129088ms
>> I1022 23:49:58.794522 28610 registrar.cpp:376] Successfully recovered
>> registrar
>> I1022 23:49:58.794577 28610 log.cpp:699] Attempting to truncate the log
>> to 1
>> I1022 23:49:58.794663 28610 master.cpp:1100] Recovered 0 slaves from the
>> Registry (101B) ; allowing 10mins for slaves to re-register
>> I1022 23:49:58.794705 28610 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 2
>> I1022 23:49:58.794883 28610 replica.cpp:508] Replica received write
>> request for position 2
>> I1022 23:49:58.795156 28610 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 260060ns
>> I1022 23:49:58.795169 28610 replica.cpp:676] Persisted action at 2
>> I1022 23:49:58.795477 28617 replica.cpp:655] Replica received learned
>> notice for position 2
>> I1022 23:49:58.795795 28617 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 298268ns
>> I1022 23:49:59.009078 28617 leveldb.cpp:401] Deleting ~1 keys from
>> leveldb took 62645ns
>> I1022 23:49:59.009115 28617 replica.cpp:676] Persisted action at 2
>> I1022 23:49:59.009127 28617 replica.cpp:661] Replica learned TRUNCATE
>> action at position 2
>> I1022 23:49:59.019134 28616 slave.cpp:169] Slave started on 92)@
>> 67.195.81.187:36297
>> I1022 23:49:59.019175 28616 credentials.hpp:84] Loading credential for
>> authentication from
>> '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/credential'
>> I1022 23:49:59.019275 28616 slave.cpp:276] Slave using credential for:
>> test-principal
>> I1022 23:49:59.019410 28616 slave.cpp:289] Slave resources: cpus(*):2;
>> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
>> I1022 23:49:59.019479 28616 slave.cpp:318] Slave hostname:
>> pomona.apache.org
>> I1022 23:49:59.019490 28616 slave.cpp:319] Slave checkpoint: false
>> I1022 23:49:59.019891 28606 state.cpp:33] Recovering state from
>> '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/meta'
>> I1022 23:49:59.020009 28606 status_update_manager.cpp:197] Recovering
>> status update manager
>> I1022 23:49:59.020110 28606 slave.cpp:3437] Finished recovery
>> I1022 23:49:59.020411 28606 slave.cpp:597] New master detected at
>> [email protected]:36297
>> I1022 23:49:59.020434 28606 slave.cpp:660] Authenticating with master
>> [email protected]:36297
>> I1022 23:49:59.020488 28606 slave.cpp:633] Detecting new master
>> I1022 23:49:59.020531 28606 status_update_manager.cpp:171] Pausing
>> sending status updates
>> I1022 23:49:59.020570 28606 authenticatee.hpp:133] Creating new client
>> SASL connection
>> I1022 23:49:59.020679 28606 master.cpp:3847] Authenticating slave(92)@
>> 67.195.81.187:36297
>> I1022 23:49:59.020791 28606 authenticator.hpp:161] Creating new server
>> SASL connection
>> I1022 23:49:59.020864 28606 authenticatee.hpp:224] Received SASL
>> authentication mechanisms: CRAM-MD5
>> I1022 23:49:59.020884 28606 authenticatee.hpp:250] Attempting to
>> authenticate with mechanism 'CRAM-MD5'
>> I1022 23:49:59.020989 28617 authenticator.hpp:267] Received SASL
>> authentication start
>> I1022 23:49:59.021031 28617 authenticator.hpp:389] Authentication
>> requires more steps
>> I1022 23:49:59.021119 28617 authenticatee.hpp:270] Received SASL
>> authentication step
>> I1022 23:49:59.021214 28617 authenticator.hpp:295] Received SASL
>> authentication step
>> I1022 23:49:59.021236 28617 auxprop.cpp:81] Request to lookup properties
>> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
>> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
>> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
>> I1022 23:49:59.021247 28617 auxprop.cpp:153] Looking up auxiliary
>> property '*userPassword'
>> I1022 23:49:59.021262 28617 auxprop.cpp:153] Looking up auxiliary
>> property '*cmusaslsecretCRAM-MD5'
>> I1022 23:49:59.021275 28617 auxprop.cpp:81] Request to lookup properties
>> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
>> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
>> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
>> I1022 23:49:59.021292 28617 auxprop.cpp:103] Skipping auxiliary property
>> '*userPassword' since SASL_AUXPROP_AUTHZID == true
>> I1022 23:49:59.021301 28617 auxprop.cpp:103] Skipping auxiliary property
>> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
>> I1022 23:49:59.021317 28617 authenticator.hpp:381] Authentication success
>> I1022 23:49:59.021363 28606 authenticatee.hpp:310] Authentication success
>> I1022 23:49:59.021374 28617 master.cpp:3887] Successfully authenticated
>> principal 'test-principal' at slave(92)@67.195.81.187:36297
>> I1022 23:49:59.021438 28606 slave.cpp:717] Successfully authenticated
>> with master [email protected]:36297
>> I1022 23:49:59.021492 28606 slave.cpp:1045] Will retry registration in
>> 942597ns if necessary
>> I1022 23:49:59.021574 28606 master.cpp:3026] Registering slave at
>> slave(92)@67.195.81.187:36297 (pomona.apache.org) with id
>> 20141022-234958-3142697795-36297-28588-S0
>> I1022 23:49:59.021716 28606 registrar.cpp:445] Applied 1 operations in
>> 14399ns; attempting to update the 'registry'
>> I1022 23:49:59.022148 28588 sched.cpp:137] Version: 0.21.0
>> I1022 23:49:59.022495 28605 sched.cpp:233] New master detected at
>> [email protected]:36297
>> I1022 23:49:59.022516 28605 sched.cpp:283] Authenticating with master
>> [email protected]:36297
>> I1022 23:49:59.022589 28608 authenticatee.hpp:133] Creating new client
>> SASL connection
>> I1022 23:49:59.022703 28604 slave.cpp:1045] Will retry registration in
>> 5.737624ms if necessary
>> I1022 23:49:59.022712 28608 master.cpp:3847] Authenticating
>> [email protected]:36297
>> I1022 23:49:59.022814 28611 authenticator.hpp:161] Creating new server
>> SASL connection
>> I1022 23:49:59.022835 28608 master.cpp:3014] Ignoring register slave
>> message from slave(92)@67.195.81.187:36297 (pomona.apache.org) as
>> admission is already in progress
>> I1022 23:49:59.022878 28608 authenticatee.hpp:224] Received SASL
>> authentication mechanisms: CRAM-MD5
>> I1022 23:49:59.022894 28608 authenticatee.hpp:250] Attempting to
>> authenticate with mechanism 'CRAM-MD5'
>> I1022 23:49:59.022933 28608 authenticator.hpp:267] Received SASL
>> authentication start
>> I1022 23:49:59.022969 28608 authenticator.hpp:389] Authentication
>> requires more steps
>> I1022 23:49:59.023084 28602 authenticatee.hpp:270] Received SASL
>> authentication step
>> I1022 23:49:59.023161 28612 authenticator.hpp:295] Received SASL
>> authentication step
>> I1022 23:49:59.023182 28612 auxprop.cpp:81] Request to lookup properties
>> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
>> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
>> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
>> I1022 23:49:59.023185 28613 log.cpp:680] Attempting to append 316 bytes
>> to the log
>> I1022 23:49:59.023191 28612 auxprop.cpp:153] Looking up auxiliary
>> property '*userPassword'
>> I1022 23:49:59.023203 28612 auxprop.cpp:153] Looking up auxiliary
>> property '*cmusaslsecretCRAM-MD5'
>> I1022 23:49:59.023214 28612 auxprop.cpp:81] Request to lookup properties
>> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
>> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
>> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
>> I1022 23:49:59.023222 28612 auxprop.cpp:103] Skipping auxiliary property
>> '*userPassword' since SASL_AUXPROP_AUTHZID == true
>> I1022 23:49:59.023228 28612 auxprop.cpp:103] Skipping auxiliary property
>> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
>> I1022 23:49:59.023241 28612 authenticator.hpp:381] Authentication success
>> I1022 23:49:59.023252 28611 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 3
>> I1022 23:49:59.023316 28602 master.cpp:3887] Successfully authenticated
>> principal 'test-principal' at
>> [email protected]:36297
>> I1022 23:49:59.023345 28603 authenticatee.hpp:310] Authentication success
>> I1022 23:49:59.023476 28612 sched.cpp:357] Successfully authenticated
>> with master [email protected]:36297
>> I1022 23:49:59.023494 28612 sched.cpp:476] Sending registration request
>> to [email protected]:36297
>> I1022 23:49:59.023669 28607 replica.cpp:508] Replica received write
>> request for position 3
>> I1022 23:49:59.023797 28605 master.cpp:1362] Received registration
>> request for framework 'default' at
>> [email protected]:36297
>> I1022 23:49:59.023816 28605 master.cpp:1321] Authorizing framework
>> principal 'test-principal' to receive offers for role '*'
>> I1022 23:49:59.023967 28614 master.cpp:1426] Registering framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:49:59.024065 28613 hierarchical_allocator_process.hpp:329] Added
>> framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.024082 28613 hierarchical_allocator_process.hpp:697] No
>> resources available to allocate!
>> I1022 23:49:59.024091 28613 hierarchical_allocator_process.hpp:659]
>> Performed allocation for 0 slaves in 9093ns
>> I1022 23:49:59.024139 28613 sched.cpp:407] Framework registered with
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.137439 28613 sched.cpp:421] Scheduler::registered took
>> 63837ns
>> I1022 23:49:59.029038 28606 slave.cpp:1045] Will retry registration in
>> 28.855729ms if necessary
>> I1022 23:49:59.024247 28607 leveldb.cpp:343] Persisting action (335
>> bytes) to leveldb took 560041ns
>> I1022 23:49:59.029153 28605 master.cpp:3014] Ignoring register slave
>> message from slave(92)@67.195.81.187:36297 (pomona.apache.org) as
>> admission is already in progress
>> I1022 23:49:59.137543 28607 replica.cpp:676] Persisted action at 3
>> I1022 23:49:59.138083 28606 replica.cpp:655] Replica received learned
>> notice for position 3
>> I1022 23:49:59.138620 28606 leveldb.cpp:343] Persisting action (337
>> bytes) to leveldb took 517056ns
>> I1022 23:49:59.138638 28606 replica.cpp:676] Persisted action at 3
>> I1022 23:49:59.138649 28606 replica.cpp:661] Replica learned APPEND
>> action at position 3
>> I1022 23:49:59.139158 28613 registrar.cpp:490] Successfully updated the
>> 'registry' in 117.417216ms
>> I1022 23:49:59.139292 28611 log.cpp:699] Attempting to truncate the log
>> to 3
>> I1022 23:49:59.139355 28603 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 4
>> I1022 23:49:59.139505 28615 master.cpp:3080] Registered slave
>> 20141022-234958-3142697795-36297-28588-S0 at slave(92)@
>> 67.195.81.187:36297 (pomona.apache.org) with cpus(*):2; mem(*):1024;
>> disk(*):1024; ports(*):[31000-32000]
>> I1022 23:49:59.139513 28611 hierarchical_allocator_process.hpp:442] Added
>> slave 20141022-234958-3142697795-36297-28588-S0 (pomona.apache.org) with
>> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
>> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
>> I1022 23:49:59.139598 28611 hierarchical_allocator_process.hpp:734]
>> Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
>> slave 20141022-234958-3142697795-36297-28588-S0 to framework
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.139669 28604 slave.cpp:2517] Received ping from
>> slave-observer(89)@67.195.81.187:36297
>> I1022 23:49:59.139720 28607 replica.cpp:508] Replica received write
>> request for position 4
>> I1022 23:49:59.139740 28604 slave.cpp:751] Registered with master
>> [email protected]:36297; given slave ID
>> 20141022-234958-3142697795-36297-28588-S0
>> I1022 23:49:59.139801 28611 hierarchical_allocator_process.hpp:679]
>> Performed allocation for slave 20141022-234958-3142697795-36297-28588-S0 in
>> 235887ns
>> I1022 23:49:59.139806 28613 status_update_manager.cpp:178] Resuming
>> sending status updates
>> I1022 23:49:59.139919 28617 master.cpp:3789] Sending 1 offers to
>> framework 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:49:59.140096 28607 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 350458ns
>> I1022 23:49:59.140111 28607 replica.cpp:676] Persisted action at 4
>> I1022 23:49:59.140264 28617 sched.cpp:544] Scheduler::resourceOffers took
>> 182145ns
>> I1022 23:49:59.140290 28607 replica.cpp:655] Replica received learned
>> notice for position 4
>> I1022 23:49:59.140535 28617 master.cpp:2315] Processing reply for offers:
>> [ 20141022-234958-3142697795-36297-28588-O0 ] on slave
>> 20141022-234958-3142697795-36297-28588-S0 at slave(92)@
>> 67.195.81.187:36297 (pomona.apache.org) for framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:49:59.140576 28607 leveldb.cpp:343] Persisting action (18
>> bytes) to leveldb took 271109ns
>> W1022 23:49:59.140578 28617 master.cpp:1969] Executor default for task 0
>> uses less CPUs (None) than the minimum required (0.01). Please update your
>> executor, as this will be mandatory in future releases.
>> W1022 23:49:59.140604 28617 master.cpp:1980] Executor default for task 0
>> uses less memory (None) than the minimum required (32MB). Please update
>> your executor, as this will be mandatory in future releases.
>> I1022 23:49:59.140612 28607 leveldb.cpp:401] Deleting ~2 keys from
>> leveldb took 19045ns
>> I1022 23:49:59.140627 28607 replica.cpp:676] Persisted action at 4
>> I1022 23:49:59.140632 28617 master.cpp:2411] Authorizing framework
>> principal 'test-principal' to launch task 0 as user 'jenkins'
>> I1022 23:49:59.140637 28607 replica.cpp:661] Replica learned TRUNCATE
>> action at position 4
>> I1022 23:49:59.140949 28617 master.hpp:877] Adding task 0 with resources
>> cpus(*):1; mem(*):512 on slave 20141022-234958-3142697795-36297-28588-S0 (
>> pomona.apache.org)
>> I1022 23:49:59.140985 28617 master.cpp:2474] Launching task 0 of
>> framework 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297 with
>> resources cpus(*):1; mem(*):512 on slave
>> 20141022-234958-3142697795-36297-28588-S0 at slave(92)@
>> 67.195.81.187:36297 (pomona.apache.org)
>> I1022 23:49:59.141108 28604 slave.cpp:1076] Got assigned task 0 for
>> framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.141242 28609 hierarchical_allocator_process.hpp:563]
>> Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]
>> (total allocatable: cpus(*):1; mem(*):512; disk(*):1024;
>> ports(*):[31000-32000]) on slave 20141022-234958-3142697795-36297-28588-S0
>> from framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.141288 28609 hierarchical_allocator_process.hpp:599]
>> Framework 20141022-234958-3142697795-36297-28588-0000 filtered slave
>> 20141022-234958-3142697795-36297-28588-S0 for 5secs
>> I1022 23:49:59.141373 28604 slave.cpp:1186] Launching task 0 for
>> framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.142989 28604 slave.cpp:3852] Launching executor default of
>> framework 20141022-234958-3142697795-36297-28588-0000 in work directory
>> '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/slaves/20141022-234958-3142697795-36297-28588-S0/frameworks/20141022-234958-3142697795-36297-28588-0000/executors/default/runs/ab333897-e649-4960-8580-9dcff92b63ec'
>> I1022 23:49:59.144456 28604 exec.cpp:132] Version: 0.21.0
>> I1022 23:49:59.144541 28617 exec.cpp:182] Executor started at:
>> executor(34)@67.195.81.187:36297 with pid 28588
>> I1022 23:49:59.144598 28604 slave.cpp:1312] Queuing task '0' for
>> executor default of framework '20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.144649 28604 slave.cpp:550] Successfully attached file
>> '/tmp/ReconciliationTest_UnacknowledgedTerminalTask_7XsYHG/slaves/20141022-234958-3142697795-36297-28588-S0/frameworks/20141022-234958-3142697795-36297-28588-0000/executors/default/runs/ab333897-e649-4960-8580-9dcff92b63ec'
>> I1022 23:49:59.144696 28604 slave.cpp:2783] Monitoring executor 'default'
>> of framework '20141022-234958-3142697795-36297-28588-0000' in container
>> 'ab333897-e649-4960-8580-9dcff92b63ec'
>> I1022 23:49:59.144783 28604 slave.cpp:1844] Got registration for executor
>> 'default' of framework 20141022-234958-3142697795-36297-28588-0000 from
>> executor(34)@67.195.81.187:36297
>> I1022 23:49:59.144930 28604 slave.cpp:1963] Flushing queued task 0 for
>> executor 'default' of framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.144966 28617 exec.cpp:206] Executor registered on slave
>> 20141022-234958-3142697795-36297-28588-S0
>> I1022 23:49:59.145961 28617 exec.cpp:218] Executor::registered took
>> 15657ns
>> I1022 23:49:59.146023 28617 exec.cpp:293] Executor asked to run task '0'
>> I1022 23:49:59.146060 28617 exec.cpp:302] Executor::launchTask took
>> 24526ns
>> I1022 23:49:59.146951 28617 exec.cpp:525] Executor sending status update
>> TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of
>> framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:49:59.147037 28617 slave.cpp:2197] Handling status update
>> TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of
>> framework 20141022-234958-3142697795-36297-28588-0000 from executor(34)@
>> 67.195.81.187:36297
>> I1022 23:49:59.147059 28617 slave.cpp:4160] Terminating task 0
>> I../../src/tests/reconciliation_tests.cpp:720: Failure
>> Failed to wait 10secs for update1
>> ../../src/tests/reconciliation_tests.cpp:703: Failure
>> Actual function call count doesn't match EXPECT_CALL(sched,
>> statusUpdate(&driver, _))...
>> Expected: to be called once
>> 1022 23:49:59.147155 28617 status_update_manager.cpp:317] Received status
>> update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task
>> 0 of framework 20141022-234958-3142697795-36297-28588-0000
>> Actual: never called - unsatisfied and active
>> I1022 23:50:09.380831 28617 status_update_manager.cpp:494] Creating
>> StatusUpdate stream for task 0 of framework
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:03.785439 28613 master.cpp:120] No whitelist given.
>> Advertising offers for all slaves
>> I1022 23:50:09.380949 28617 status_update_manager.cpp:371] Forwarding
>> update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task
>> 0 of framework 20141022-234958-3142697795-36297-28588-0000 to the slave
>> I1022 23:50:09.380975 28606 master.cpp:768] Framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> disconnected
>> I1022 23:49:59.785217 28602 hierarchical_allocator_process.hpp:816]
>> Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on
>> slave 20141022-234958-3142697795-36297-28588-S0 for framework
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:09.380996 28606 master.cpp:1731] Disconnecting framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:50:09.381009 28606 master.cpp:1747] Deactivating framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:50:09.381032 28606 master.cpp:790] Giving framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297 0ns
>> to failover
>> I1022 23:50:09.381029 28602 hierarchical_allocator_process.hpp:659]
>> Performed allocation for 1 slaves in 9.59591129secs
>> I1022 23:50:09.381116 28602 hierarchical_allocator_process.hpp:405]
>> Deactivated framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:09.381554 28606 slave.cpp:2437] Forwarding the update
>> TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of
>> framework 20141022-234958-3142697795-36297-28588-0000 to
>> [email protected]:36297
>> I1022 23:50:09.381731 28615 master.cpp:3659] Framework failover timeout,
>> removing framework 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> I1022 23:50:09.381752 28615 master.cpp:4195] Removing framework
>> 20141022-234958-3142697795-36297-28588-0000 (default) at
>> [email protected]:36297
>> W1022 23:50:09.381784 28615 master.cpp:4636] Removing task 0 with
>> resources cpus(*):1; mem(*):512 of framework
>> 20141022-234958-3142697795-36297-28588-0000 on slave
>> 20141022-234958-3142697795-36297-28588-S0 at slave(92)@
>> 67.195.81.187:36297 (pomona.apache.org) in non-terminal state
>> TASK_STAGING
>> I1022 23:50:09.381868 28606 slave.cpp:2364] Status update manager
>> successfully handled status update TASK_FINISHED (UUID:
>> 9eedb006-7959-48e3-bd57-b460298fc842) for task 0 of framework
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:09.381885 28606 slave.cpp:2370] Sending acknowledgement for
>> status update TASK_FINISHED (UUID: 9eedb006-7959-48e3-bd57-b460298fc842)
>> for task 0 of framework 20141022-234958-3142697795-36297-28588-0000 to
>> executor(34)@67.195.81.187:36297
>> I1022 23:50:09.381944 28606 slave.cpp:1517] Asked to shut down framework
>> 20141022-234958-3142697795-36297-28588-0000 by [email protected]:36297
>> I1022 23:50:09.381959 28606 slave.cpp:1542] Shutting down framework
>> 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:09.381976 28606 slave.cpp:3117] Shutting down executor
>> 'default' of framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:09.382115 28607 hierarchical_allocator_process.hpp:563]
>> Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024;
>> disk(*):1024; ports(*):[31000-32000]) on slave
>> 20141022-234958-3142697795-36297-28588-S0 from framework
>> 20141022-234958-3142697795-36297-28588-0000
>> F1022 23:50:10.381491 28602 logging.cpp:57] RAW: Pure virtual method
>> called
>> I1022 23:50:09.382222 28615 master.cpp:4679] Removing executor 'default'
>> with resources of framework 20141022-234958-3142697795-36297-28588-0000 on
>> slave 20141022-234958-3142697795-36297-28588-S0 at slave(92)@
>> 67.195.81.187:36297 (pomona.apache.org)
>> I1022 23:50:10.381491 28613 hierarchical_allocator_process.hpp:659]
>> Performed allocation for 1 slaves in 30737ns
>> I1022 23:50:12.877471 28617 hierarchical_allocator_process.hpp:360]
>> Removed framework 20141022-234958-3142697795-36297-28588-0000
>> I1022 23:50:12.877516 28615 master.cpp:677] Master terminating
>> I1022 23:50:12.877804 28608 slave.cpp:2602] [email protected]:36297
>> exited
>> W1022 23:50:12.877830 28608 slave.cpp:2605] Master disconnected! Waiting
>> for a new master to be elected
>> F1022 23:50:12.877830 28588 logging.cpp:57] RAW: Pure virtual method
>> called
>> @ 0x2b89187e25dd google::LogMessage::Fail()
>> @ 0x2b89187e9cd6 google::RawLog__()
>> @ 0x2b89183f84d9
>> mesos::internal::slave::ResourceMonitorProcess::collect()
>> @ 0x2b89187a439a process::ProcessManager::resume()
>> @ 0x2b89187e25dd google::LogMessage::Fail()
>> @ 0x2b89187a465c process::schedule()
>> @ 0x2b89187e9cd6 google::RawLog__()
>> @ 0x507226
>> mesos::internal::tests::Cluster::Slaves::shutdown()
>> @ 0x7a7f24
>> mesos::internal::tests::MesosTest::ShutdownSlaves()
>> @ 0x9a4713
>> testing::internal::HandleExceptionsInMethodIfSupported<>()
>> @ 0x99b980 testing::Test::Run()
>> @ 0x99ba5e testing::TestInfo::Run()
>> @ 0x99bb65 testing::TestCase::Run()
>> @ 0x99be08 testing::internal::UnitTestImpl::RunAllTests()
>> @ 0x99c0a7 testing::UnitTest::Run()
>> @ 0x490aca main
>> @ 0x2b891a707ec5 (unknown)
>> @ 0x49dfa8 (unknown)
>> make[3]: *** [check-local] Aborted
>> make[3]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make[2]: *** [check-am] Error 2
>> make[2]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make[1]: *** [check] Error 2
>> make[1]: Leaving directory `<
>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>> '>
>> make: *** [check-recursive] Error 1
>> Test finished
>> Exit status: 2
>> Build step 'Execute shell' marked build as failure
>> Recording test results
>>
>
>
