[
https://issues.apache.org/jira/browse/MESOS-2403?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vinod Kone resolved MESOS-2403.
-------------------------------
Resolution: Fixed
Fix Version/s: 0.23.0
commit 11c357bf07e7cbe381a6786aaefb9f5460b68c35
Author: Vinod Kone <[email protected]>
Date: Mon Mar 2 14:19:37 2015 -0800
Fixed Master::finalize() to remove slaves and frameworks from the allocator.
Short term fix for MESOS-2403.
Review: https://reviews.apache.org/r/31644
> MasterAllocatorTest/0.FrameworkReregistersFirst is flaky
> --------------------------------------------------------
>
> Key: MESOS-2403
> URL: https://issues.apache.org/jira/browse/MESOS-2403
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.23.0
> Environment: ASF CI (Ubuntu)
> Reporter: Vinod Kone
> Assignee: Vinod Kone
> Fix For: 0.23.0
>
>
> {code}
> [ RUN ] MasterAllocatorTest/0.FrameworkReregistersFirst
> Using temporary directory
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml'
> I0224 23:22:31.681670 30589 leveldb.cpp:176] Opened db in 2.943518ms
> I0224 23:22:31.682152 30619 process.cpp:2117] Dropped / Lost event for PID:
> slave(65)@67.195.81.187:38391
> I0224 23:22:31.682732 30589 leveldb.cpp:183] Compacted db in 1.029469ms
> I0224 23:22:31.682777 30589 leveldb.cpp:198] Created db iterator in 15460ns
> I0224 23:22:31.682792 30589 leveldb.cpp:204] Seeked to beginning of db in
> 1832ns
> I0224 23:22:31.682802 30589 leveldb.cpp:273] Iterated through 0 keys in the
> db in 319ns
> I0224 23:22:31.682833 30589 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0224 23:22:31.683228 30605 recover.cpp:449] Starting replica recovery
> I0224 23:22:31.683537 30605 recover.cpp:475] Replica is in 4 status
> I0224 23:22:31.684624 30615 replica.cpp:641] Replica in 4 status received a
> broadcasted recover request
> I0224 23:22:31.684978 30616 recover.cpp:195] Received a recover response from
> a replica in 4 status
> I0224 23:22:31.685405 30610 recover.cpp:566] Updating replica status to 3
> I0224 23:22:31.686249 30609 master.cpp:349] Master
> 20150224-232231-3142697795-38391-30589 (pomona.apache.org) started on
> 67.195.81.187:38391
> I0224 23:22:31.686265 30617 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 717897ns
> I0224 23:22:31.686319 30617 replica.cpp:323] Persisted replica status to 3
> I0224 23:22:31.686336 30609 master.cpp:395] Master only allowing
> authenticated frameworks to register
> I0224 23:22:31.686357 30609 master.cpp:400] Master only allowing
> authenticated slaves to register
> I0224 23:22:31.686390 30609 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml/credentials'
> I0224 23:22:31.686511 30606 recover.cpp:475] Replica is in 3 status
> I0224 23:22:31.686563 30609 master.cpp:442] Authorization enabled
> I0224 23:22:31.686929 30607 whitelist_watcher.cpp:79] No whitelist given
> I0224 23:22:31.686954 30603 hierarchical.hpp:287] Initialized hierarchical
> allocator process
> I0224 23:22:31.687134 30605 replica.cpp:641] Replica in 3 status received a
> broadcasted recover request
> I0224 23:22:31.687731 30609 master.cpp:1356] The newly elected leader is
> [email protected]:38391 with id 20150224-232231-3142697795-38391-30589
> I0224 23:22:31.839818 30609 master.cpp:1369] Elected as the leading master!
> I0224 23:22:31.839834 30609 master.cpp:1187] Recovering from registrar
> I0224 23:22:31.839926 30605 registrar.cpp:313] Recovering registrar
> I0224 23:22:31.840000 30613 recover.cpp:195] Received a recover response from
> a replica in 3 status
> I0224 23:22:31.840504 30606 recover.cpp:566] Updating replica status to 1
> I0224 23:22:31.841599 30611 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 990330ns
> I0224 23:22:31.841627 30611 replica.cpp:323] Persisted replica status to 1
> I0224 23:22:31.841743 30611 recover.cpp:580] Successfully joined the Paxos
> group
> I0224 23:22:31.841904 30611 recover.cpp:464] Recover process terminated
> I0224 23:22:31.842366 30608 log.cpp:660] Attempting to start the writer
> I0224 23:22:31.843557 30607 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0224 23:22:31.844312 30607 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 722368ns
> I0224 23:22:31.844337 30607 replica.cpp:345] Persisted promised to 1
> I0224 23:22:31.844889 30615 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0224 23:22:31.846043 30614 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0224 23:22:31.846729 30614 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 660024ns
> I0224 23:22:31.846746 30614 replica.cpp:679] Persisted action at 0
> I0224 23:22:31.847671 30611 replica.cpp:511] Replica received write request
> for position 0
> I0224 23:22:31.847723 30611 leveldb.cpp:438] Reading position from leveldb
> took 27349ns
> I0224 23:22:31.848429 30611 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 671461ns
> I0224 23:22:31.848454 30611 replica.cpp:679] Persisted action at 0
> I0224 23:22:31.849041 30615 replica.cpp:658] Replica received learned notice
> for position 0
> I0224 23:22:31.849762 30615 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 690386ns
> I0224 23:22:31.849787 30615 replica.cpp:679] Persisted action at 0
> I0224 23:22:31.849808 30615 replica.cpp:664] Replica learned 1 action at
> position 0
> I0224 23:22:31.850416 30612 log.cpp:676] Writer started with ending position 0
> I0224 23:22:31.851490 30615 leveldb.cpp:438] Reading position from leveldb
> took 30659ns
> I0224 23:22:31.854452 30610 registrar.cpp:346] Successfully fetched the
> registry (0B) in 14.491136ms
> I0224 23:22:31.854543 30610 registrar.cpp:445] Applied 1 operations in
> 18024ns; attempting to update the 'registry'
> I0224 23:22:31.857095 30604 log.cpp:684] Attempting to append 139 bytes to
> the log
> I0224 23:22:31.857208 30608 coordinator.cpp:340] Coordinator attempting to
> write 2 action at position 1
> I0224 23:22:31.858073 30609 replica.cpp:511] Replica received write request
> for position 1
> I0224 23:22:31.858808 30609 leveldb.cpp:343] Persisting action (158 bytes) to
> leveldb took 701708ns
> I0224 23:22:31.858835 30609 replica.cpp:679] Persisted action at 1
> I0224 23:22:31.859508 30618 replica.cpp:658] Replica received learned notice
> for position 1
> I0224 23:22:31.860267 30618 leveldb.cpp:343] Persisting action (160 bytes) to
> leveldb took 731035ns
> I0224 23:22:31.860309 30618 replica.cpp:679] Persisted action at 1
> I0224 23:22:31.860332 30618 replica.cpp:664] Replica learned 2 action at
> position 1
> I0224 23:22:31.860983 30609 registrar.cpp:490] Successfully updated the
> 'registry' in 6.39616ms
> I0224 23:22:31.861071 30609 registrar.cpp:376] Successfully recovered
> registrar
> I0224 23:22:31.861126 30608 log.cpp:703] Attempting to truncate the log to 1
> I0224 23:22:31.861249 30603 coordinator.cpp:340] Coordinator attempting to
> write 3 action at position 2
> I0224 23:22:31.861248 30617 master.cpp:1214] Recovered 0 slaves from the
> Registry (101B) ; allowing 10mins for slaves to re-register
> I0224 23:22:31.861831 30613 replica.cpp:511] Replica received write request
> for position 2
> I0224 23:22:31.862504 30613 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 648125ns
> I0224 23:22:31.862531 30613 replica.cpp:679] Persisted action at 2
> I0224 23:22:31.863067 30603 replica.cpp:658] Replica received learned notice
> for position 2
> I0224 23:22:31.863689 30603 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 602784ns
> I0224 23:22:31.863737 30603 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 28697ns
> I0224 23:22:31.863751 30603 replica.cpp:679] Persisted action at 2
> I0224 23:22:31.863767 30603 replica.cpp:664] Replica learned 3 action at
> position 2
> I0224 23:22:31.875962 30610 slave.cpp:174] Slave started on
> 66)@67.195.81.187:38391
> I0224 23:22:31.876008 30610 credentials.hpp:85] Loading credential for
> authentication from
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/credential'
> I0224 23:22:31.876144 30610 slave.cpp:281] Slave using credential for:
> test-principal
> I0224 23:22:31.876404 30610 slave.cpp:299] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0224 23:22:31.876489 30610 slave.cpp:328] Slave hostname: pomona.apache.org
> I0224 23:22:31.876502 30610 slave.cpp:329] Slave checkpoint: false
> W0224 23:22:31.876507 30610 slave.cpp:331] Disabling checkpointing is
> deprecated and the --checkpoint flag will be removed in a future release.
> Please avoid using this flag
> I0224 23:22:31.877014 30603 state.cpp:35] Recovering state from
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/meta'
> I0224 23:22:31.877230 30610 status_update_manager.cpp:197] Recovering status
> update manager
> I0224 23:22:31.877495 30609 slave.cpp:3776] Finished recovery
> I0224 23:22:31.877879 30607 status_update_manager.cpp:171] Pausing sending
> status updates
> I0224 23:22:31.877879 30604 slave.cpp:624] New master detected at
> [email protected]:38391
> I0224 23:22:31.877959 30604 slave.cpp:687] Authenticating with master
> [email protected]:38391
> I0224 23:22:31.877975 30604 slave.cpp:692] Using default CRAM-MD5
> authenticatee
> I0224 23:22:31.878069 30604 slave.cpp:660] Detecting new master
> I0224 23:22:31.878093 30608 authenticatee.hpp:139] Creating new client SASL
> connection
> I0224 23:22:31.878223 30604 master.cpp:3813] Authenticating
> slave(66)@67.195.81.187:38391
> I0224 23:22:31.878244 30604 master.cpp:3824] Using default CRAM-MD5
> authenticator
> I0224 23:22:31.878412 30613 authenticator.hpp:170] Creating new server SASL
> connection
> I0224 23:22:31.878525 30603 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0224 23:22:31.878551 30603 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0224 23:22:31.878625 30617 authenticator.hpp:276] Received SASL
> authentication start
> I0224 23:22:31.878662 30617 authenticator.hpp:398] Authentication requires
> more steps
> I0224 23:22:31.878727 30603 authenticatee.hpp:276] Received SASL
> authentication step
> I0224 23:22:31.878815 30617 authenticator.hpp:304] Received SASL
> authentication step
> I0224 23:22:31.878839 30617 auxprop.cpp:99] 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
> I0224 23:22:31.878847 30617 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0224 23:22:31.878875 30617 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0224 23:22:31.878891 30617 auxprop.cpp:99] 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
> I0224 23:22:31.878900 30617 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:31.878906 30617 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:31.878916 30617 authenticator.hpp:390] Authentication success
> I0224 23:22:31.880717 30589 sched.cpp:157] Version: 0.23.0
> I0224 23:22:32.017823 30611 authenticatee.hpp:316] Authentication success
> I0224 23:22:32.017901 30618 master.cpp:3871] Successfully authenticated
> principal 'test-principal' at slave(66)@67.195.81.187:38391
> I0224 23:22:32.018156 30615 sched.cpp:254] New master detected at
> [email protected]:38391
> I0224 23:22:32.018240 30615 sched.cpp:310] Authenticating with master
> [email protected]:38391
> I0224 23:22:32.018263 30615 sched.cpp:317] Using default CRAM-MD5
> authenticatee
> I0224 23:22:32.018496 30613 slave.cpp:758] Successfully authenticated with
> master [email protected]:38391
> I0224 23:22:32.018579 30611 authenticatee.hpp:139] Creating new client SASL
> connection
> I0224 23:22:32.018620 30613 slave.cpp:1090] Will retry registration in
> 363167ns if necessary
> I0224 23:22:32.018811 30615 master.cpp:2938] Registering slave at
> slave(66)@67.195.81.187:38391 (pomona.apache.org) with id
> 20150224-232231-3142697795-38391-30589-S0
> I0224 23:22:32.019122 30615 master.cpp:3813] Authenticating
> [email protected]:38391
> I0224 23:22:32.019156 30615 master.cpp:3824] Using default CRAM-MD5
> authenticator
> I0224 23:22:32.019232 30612 registrar.cpp:445] Applied 1 operations in
> 57599ns; attempting to update the 'registry'
> I0224 23:22:32.019394 30603 authenticator.hpp:170] Creating new server SASL
> connection
> I0224 23:22:32.019541 30611 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0224 23:22:32.019568 30611 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0224 23:22:32.019666 30605 authenticator.hpp:276] Received SASL
> authentication start
> I0224 23:22:32.019717 30605 authenticator.hpp:398] Authentication requires
> more steps
> I0224 23:22:32.019805 30615 authenticatee.hpp:276] Received SASL
> authentication step
> I0224 23:22:32.019942 30605 authenticator.hpp:304] Received SASL
> authentication step
> I0224 23:22:32.019979 30605 auxprop.cpp:99] 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
> I0224 23:22:32.019994 30605 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0224 23:22:32.020025 30605 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0224 23:22:32.020036 30610 slave.cpp:1090] Will retry registration in
> 10.850555ms if necessary
> I0224 23:22:32.020053 30605 auxprop.cpp:99] 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
> I0224 23:22:32.020102 30605 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.020117 30605 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.020133 30605 authenticator.hpp:390] Authentication success
> I0224 23:22:32.020151 30611 master.cpp:2926] Ignoring register slave message
> from slave(66)@67.195.81.187:38391 (pomona.apache.org) as admission is
> already in progress
> I0224 23:22:32.020226 30603 authenticatee.hpp:316] Authentication success
> I0224 23:22:32.020256 30611 master.cpp:3871] Successfully authenticated
> principal 'test-principal' at
> [email protected]:38391
> I0224 23:22:32.020534 30615 sched.cpp:398] Successfully authenticated with
> master [email protected]:38391
> I0224 23:22:32.020561 30615 sched.cpp:521] Sending registration request to
> [email protected]:38391
> I0224 23:22:32.020635 30615 sched.cpp:554] Will retry registration in
> 490.035142ms if necessary
> I0224 23:22:32.020720 30613 master.cpp:1574] Received registration request
> for framework 'default' at
> [email protected]:38391
> I0224 23:22:32.020787 30613 master.cpp:1435] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0224 23:22:32.021122 30607 master.cpp:1638] Registering framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.021502 30611 hierarchical.hpp:321] Added framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.021531 30611 hierarchical.hpp:834] No resources available to
> allocate!
> I0224 23:22:32.021543 30611 hierarchical.hpp:741] Performed allocation for 0
> slaves in 18915ns
> I0224 23:22:32.021618 30609 sched.cpp:448] Framework registered with
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.021673 30609 sched.cpp:462] Scheduler::registered took 26310ns
> I0224 23:22:32.022400 30613 log.cpp:684] Attempting to append 316 bytes to
> the log
> I0224 23:22:32.022523 30608 coordinator.cpp:340] Coordinator attempting to
> write 2 action at position 3
> I0224 23:22:32.023232 30607 replica.cpp:511] Replica received write request
> for position 3
> I0224 23:22:32.024055 30607 leveldb.cpp:343] Persisting action (335 bytes) to
> leveldb took 798548ns
> I0224 23:22:32.024073 30607 replica.cpp:679] Persisted action at 3
> I0224 23:22:32.024651 30610 replica.cpp:658] Replica received learned notice
> for position 3
> I0224 23:22:32.025252 30610 leveldb.cpp:343] Persisting action (337 bytes) to
> leveldb took 580525ns
> I0224 23:22:32.025271 30610 replica.cpp:679] Persisted action at 3
> I0224 23:22:32.025297 30610 replica.cpp:664] Replica learned 2 action at
> position 3
> I0224 23:22:32.025995 30618 registrar.cpp:490] Successfully updated the
> 'registry' in 6.586112ms
> I0224 23:22:32.026228 30604 log.cpp:703] Attempting to truncate the log to 3
> I0224 23:22:32.026360 30609 coordinator.cpp:340] Coordinator attempting to
> write 3 action at position 4
> I0224 23:22:32.026669 30609 slave.cpp:2831] Received ping from
> slave-observer(66)@67.195.81.187:38391
> I0224 23:22:32.026772 30609 slave.cpp:792] Registered with master
> [email protected]:38391; given slave ID
> 20150224-232231-3142697795-38391-30589-S0
> I0224 23:22:32.026737 30603 master.cpp:2995] Registered slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0224 23:22:32.026867 30603 status_update_manager.cpp:178] Resuming sending
> status updates
> I0224 23:22:32.026868 30617 hierarchical.hpp:455] Added slave
> 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org) with cpus(*):2;
> mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] available)
> I0224 23:22:32.026921 30615 replica.cpp:511] Replica received write request
> for position 4
> I0224 23:22:32.027276 30617 hierarchical.hpp:759] Performed allocation for
> slave 20150224-232231-3142697795-38391-30589-S0 in 351257ns
> I0224 23:22:32.027580 30615 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 624249ns
> I0224 23:22:32.027604 30615 replica.cpp:679] Persisted action at 4
> I0224 23:22:32.027642 30618 master.cpp:3755] Sending 1 offers to framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.028223 30617 replica.cpp:658] Replica received learned notice
> for position 4
> I0224 23:22:32.028621 30607 sched.cpp:611] Scheduler::resourceOffers took
> 648326ns
> I0224 23:22:32.028916 30617 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 662416ns
> I0224 23:22:32.028991 30617 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 47386ns
> I0224 23:22:32.029021 30617 replica.cpp:679] Persisted action at 4
> I0224 23:22:32.029044 30617 replica.cpp:664] Replica learned 3 action at
> position 4
> I0224 23:22:32.029534 30613 master.cpp:2268] Processing ACCEPT call for
> offers: [ 20150224-232231-3142697795-38391-30589-O0 ] on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org) for framework 20150224-232231-3142697795-38391-30589-0000
> (default) at
> [email protected]:38391
> I0224 23:22:32.190521 30613 master.cpp:2112] Authorizing framework principal
> 'test-principal' to launch task 0 as user 'jenkins'
> W0224 23:22:32.191864 30604 validation.cpp:328] 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.
> W0224 23:22:32.191905 30604 validation.cpp:340] 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.
> I0224 23:22:32.192206 30604 master.hpp:822] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 20150224-232231-3142697795-38391-30589-S0
> (pomona.apache.org)
> I0224 23:22:32.192318 30604 master.cpp:2545] Launching task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391 with
> resources cpus(*):1; mem(*):500 on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.192659 30611 slave.cpp:1121] Got assigned task 0 for framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.192847 30609 hierarchical.hpp:648] Recovered cpus(*):1;
> mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable:
> cpus(*):1; mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave
> 20150224-232231-3142697795-38391-30589-S0 from framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.192916 30609 hierarchical.hpp:684] Framework
> 20150224-232231-3142697795-38391-30589-0000 filtered slave
> 20150224-232231-3142697795-38391-30589-S0 for 5secs
> I0224 23:22:32.193327 30611 slave.cpp:1231] Launching task 0 for framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.196038 30611 slave.cpp:4178] Launching executor default of
> framework 20150224-232231-3142697795-38391-30589-0000 in work directory
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472'
> I0224 23:22:32.197996 30611 exec.cpp:132] Version: 0.23.0
> I0224 23:22:32.198206 30605 exec.cpp:182] Executor started at:
> executor(32)@67.195.81.187:38391 with pid 30589
> I0224 23:22:32.198314 30611 slave.cpp:1378] Queuing task '0' for executor
> default of framework '20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.198407 30611 slave.cpp:577] Successfully attached file
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472'
> I0224 23:22:32.198508 30611 slave.cpp:3133] Monitoring executor 'default' of
> framework '20150224-232231-3142697795-38391-30589-0000' in container
> '7c203619-b40f-4d0a-9b75-9ddeecb63472'
> I0224 23:22:32.198637 30611 slave.cpp:2141] Got registration for executor
> 'default' of framework 20150224-232231-3142697795-38391-30589-0000 from
> executor(32)@67.195.81.187:38391
> I0224 23:22:32.198839 30604 exec.cpp:206] Executor registered on slave
> 20150224-232231-3142697795-38391-30589-S0
> I0224 23:22:32.199090 30611 slave.cpp:1532] Sending queued task '0' to
> executor 'default' of framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.200916 30604 exec.cpp:218] Executor::registered took 24976ns
> I0224 23:22:32.201087 30604 exec.cpp:293] Executor asked to run task '0'
> I0224 23:22:32.201164 30604 exec.cpp:302] Executor::launchTask took 54201ns
> I0224 23:22:32.203301 30604 exec.cpp:525] Executor sending status update
> TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of
> framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.203533 30618 slave.cpp:2508] Handling status update
> TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of
> framework 20150224-232231-3142697795-38391-30589-0000 from
> executor(32)@67.195.81.187:38391
> I0224 23:22:32.203799 30604 status_update_manager.cpp:317] Received status
> update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0
> of framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.203840 30604 status_update_manager.cpp:494] Creating
> StatusUpdate stream for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.204038 30604 status_update_manager.cpp:371] Forwarding update
> TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of
> framework 20150224-232231-3142697795-38391-30589-0000 to the slave
> I0224 23:22:32.204262 30607 slave.cpp:2751] Forwarding the update
> TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of
> framework 20150224-232231-3142697795-38391-30589-0000 to
> [email protected]:38391
> I0224 23:22:32.204473 30607 slave.cpp:2678] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.204511 30607 slave.cpp:2684] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for
> task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to
> executor(32)@67.195.81.187:38391
> I0224 23:22:32.204558 30616 master.cpp:3295] Status update TASK_RUNNING
> (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000 from slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.204602 30616 master.cpp:3336] Forwarding status update
> TASK_RUNNING (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of
> framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.204676 30610 exec.cpp:339] Executor received status update
> acknowledgement 49340611-fb39-423b-96f6-6c1e724c1a53 for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.204753 30616 master.cpp:4615] Updating the latest state of
> task 0 of framework 20150224-232231-3142697795-38391-30589-0000 to
> TASK_RUNNING
> I0224 23:22:32.204874 30603 sched.cpp:717] Scheduler::statusUpdate took
> 52057ns
> I0224 23:22:32.205277 30614 master.cpp:2782] Forwarding status update
> acknowledgement 49340611-fb39-423b-96f6-6c1e724c1a53 for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391 to slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.205579 30618 status_update_manager.cpp:389] Received status
> update acknowledgement (UUID: 49340611-fb39-423b-96f6-6c1e724c1a53) for task
> 0 of framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.205798 30604 slave.cpp:2081] Status update manager
> successfully handled status update acknowledgement (UUID:
> 49340611-fb39-423b-96f6-6c1e724c1a53) for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.206073 30607 master.cpp:787] Master terminating
> W0224 23:22:32.206197 30607 master.cpp:4668] Removing task 0 with resources
> cpus(*):1; mem(*):500 of framework
> 20150224-232231-3142697795-38391-30589-0000 on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org) in non-terminal state TASK_RUNNING
> I0224 23:22:32.206420 30614 hierarchical.hpp:648] Recovered cpus(*):1;
> mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):3.70122e+06;
> ports(*):[31000-32000]) on slave 20150224-232231-3142697795-38391-30589-S0
> from framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.206552 30607 master.cpp:4711] Removing executor 'default' with
> resources of framework 20150224-232231-3142697795-38391-30589-0000 on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.321058 30619 process.cpp:2117] Dropped / Lost event for PID:
> hierarchical-allocator(81)@67.195.81.187:38391
> I0224 23:22:32.367074 30612 slave.cpp:2916] [email protected]:38391 exited
> W0224 23:22:32.367101 30612 slave.cpp:2919] Master disconnected! Waiting for
> a new master to be elected
> I0224 23:22:32.368388 30589 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.368482 30589 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.375794 30589 leveldb.cpp:176] Opened db in 3.725405ms
> I0224 23:22:32.379137 30589 leveldb.cpp:183] Compacted db in 3.309337ms
> I0224 23:22:32.379196 30589 leveldb.cpp:198] Created db iterator in 21994ns
> I0224 23:22:32.379236 30589 leveldb.cpp:204] Seeked to beginning of db in
> 20370ns
> I0224 23:22:32.379356 30589 leveldb.cpp:273] Iterated through 3 keys in the
> db in 102640ns
> I0224 23:22:32.379411 30589 replica.cpp:744] Replica recovered with log
> positions 3 -> 4 with 0 holes and 0 unlearned
> I0224 23:22:32.379884 30610 recover.cpp:449] Starting replica recovery
> I0224 23:22:32.380156 30610 recover.cpp:475] Replica is in 1 status
> I0224 23:22:32.380460 30610 recover.cpp:464] Recover process terminated
> I0224 23:22:32.381878 30616 master.cpp:349] Master
> 20150224-232232-3142697795-38391-30589 (pomona.apache.org) started on
> 67.195.81.187:38391
> I0224 23:22:32.381927 30616 master.cpp:395] Master only allowing
> authenticated frameworks to register
> I0224 23:22:32.381945 30616 master.cpp:400] Master only allowing
> authenticated slaves to register
> I0224 23:22:32.381974 30616 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Vy5Nml/credentials'
> I0224 23:22:32.382220 30616 master.cpp:442] Authorization enabled
> I0224 23:22:32.382783 30604 whitelist_watcher.cpp:79] No whitelist given
> I0224 23:22:32.382861 30607 hierarchical.hpp:287] Initialized hierarchical
> allocator process
> I0224 23:22:32.384114 30616 master.cpp:1356] The newly elected leader is
> [email protected]:38391 with id 20150224-232232-3142697795-38391-30589
> I0224 23:22:32.384150 30616 master.cpp:1369] Elected as the leading master!
> I0224 23:22:32.384178 30616 master.cpp:1187] Recovering from registrar
> I0224 23:22:32.384330 30617 registrar.cpp:313] Recovering registrar
> I0224 23:22:32.384851 30606 log.cpp:660] Attempting to start the writer
> I0224 23:22:32.386044 30615 replica.cpp:477] Replica received implicit
> promise request with proposal 2
> I0224 23:22:32.386862 30615 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 790008ns
> I0224 23:22:32.386888 30615 replica.cpp:345] Persisted promised to 2
> I0224 23:22:32.387544 30612 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0224 23:22:32.387799 30615 log.cpp:676] Writer started with ending position 4
> I0224 23:22:32.388854 30606 leveldb.cpp:438] Reading position from leveldb
> took 51391ns
> I0224 23:22:32.388949 30606 leveldb.cpp:438] Reading position from leveldb
> took 40544ns
> I0224 23:22:32.390015 30611 registrar.cpp:346] Successfully fetched the
> registry (277B) in 5.604096ms
> I0224 23:22:32.390182 30611 registrar.cpp:445] Applied 1 operations in
> 46501ns; attempting to update the 'registry'
> I0224 23:22:32.392963 30608 log.cpp:684] Attempting to append 316 bytes to
> the log
> I0224 23:22:32.393081 30606 coordinator.cpp:340] Coordinator attempting to
> write 2 action at position 5
> I0224 23:22:32.393875 30607 replica.cpp:511] Replica received write request
> for position 5
> I0224 23:22:32.394582 30607 leveldb.cpp:343] Persisting action (335 bytes) to
> leveldb took 675133ns
> I0224 23:22:32.394609 30607 replica.cpp:679] Persisted action at 5
> I0224 23:22:32.395190 30614 replica.cpp:658] Replica received learned notice
> for position 5
> I0224 23:22:32.395917 30614 leveldb.cpp:343] Persisting action (337 bytes) to
> leveldb took 701360ns
> I0224 23:22:32.395944 30614 replica.cpp:679] Persisted action at 5
> I0224 23:22:32.395966 30614 replica.cpp:664] Replica learned 2 action at
> position 5
> I0224 23:22:32.396880 30614 registrar.cpp:490] Successfully updated the
> 'registry' in 6.644224ms
> I0224 23:22:32.397056 30614 registrar.cpp:376] Successfully recovered
> registrar
> I0224 23:22:32.397111 30604 log.cpp:703] Attempting to truncate the log to 5
> I0224 23:22:32.397274 30616 coordinator.cpp:340] Coordinator attempting to
> write 3 action at position 6
> I0224 23:22:32.397708 30615 master.cpp:1214] Recovered 1 slaves from the
> Registry (277B) ; allowing 10mins for slaves to re-register
> I0224 23:22:32.398107 30612 replica.cpp:511] Replica received write request
> for position 6
> I0224 23:22:32.398763 30612 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 625992ns
> I0224 23:22:32.398789 30612 replica.cpp:679] Persisted action at 6
> I0224 23:22:32.399373 30615 replica.cpp:658] Replica received learned notice
> for position 6
> I0224 23:22:32.400152 30615 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 754us
> I0224 23:22:32.400228 30615 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 39811ns
> I0224 23:22:32.400250 30615 replica.cpp:679] Persisted action at 6
> I0224 23:22:32.400274 30615 replica.cpp:664] Replica learned 3 action at
> position 6
> I0224 23:22:32.410408 30604 sched.cpp:248] Scheduler::disconnected took
> 15348ns
> I0224 23:22:32.410430 30604 sched.cpp:254] New master detected at
> [email protected]:38391
> I0224 23:22:32.410508 30604 sched.cpp:310] Authenticating with master
> [email protected]:38391
> I0224 23:22:32.410531 30604 sched.cpp:317] Using default CRAM-MD5
> authenticatee
> I0224 23:22:32.410781 30605 authenticatee.hpp:139] Creating new client SASL
> connection
> I0224 23:22:32.410964 30608 master.cpp:3813] Authenticating
> [email protected]:38391
> I0224 23:22:32.410991 30608 master.cpp:3824] Using default CRAM-MD5
> authenticator
> I0224 23:22:32.411188 30617 authenticator.hpp:170] Creating new server SASL
> connection
> I0224 23:22:32.411362 30612 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0224 23:22:32.411391 30612 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0224 23:22:32.411499 30618 authenticator.hpp:276] Received SASL
> authentication start
> I0224 23:22:32.411600 30618 authenticator.hpp:398] Authentication requires
> more steps
> I0224 23:22:32.411710 30614 authenticatee.hpp:276] Received SASL
> authentication step
> I0224 23:22:32.411818 30618 authenticator.hpp:304] Received SASL
> authentication step
> I0224 23:22:32.411849 30618 auxprop.cpp:99] 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
> I0224 23:22:32.411861 30618 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0224 23:22:32.411897 30618 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0224 23:22:32.411922 30618 auxprop.cpp:99] 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
> I0224 23:22:32.411934 30618 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.411942 30618 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.411958 30618 authenticator.hpp:390] Authentication success
> I0224 23:22:32.412032 30614 authenticatee.hpp:316] Authentication success
> I0224 23:22:32.412061 30612 master.cpp:3871] Successfully authenticated
> principal 'test-principal' at
> [email protected]:38391
> I0224 23:22:32.412345 30605 sched.cpp:398] Successfully authenticated with
> master [email protected]:38391
> I0224 23:22:32.412375 30605 sched.cpp:521] Sending registration request to
> [email protected]:38391
> I0224 23:22:32.528939 30605 sched.cpp:554] Will retry registration in
> 718.250035ms if necessary
> I0224 23:22:32.529072 30605 sched.cpp:521] Sending registration request to
> [email protected]:38391
> I0224 23:22:32.529136 30605 sched.cpp:554] Will retry registration in
> 2.186117614secs if necessary
> I0224 23:22:32.529161 30618 master.cpp:1711] Received re-registration request
> from framework 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.529274 30618 master.cpp:1435] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0224 23:22:32.529597 30618 master.cpp:1711] Received re-registration request
> from framework 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.529662 30618 master.cpp:1435] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0224 23:22:32.529856 30618 master.cpp:1764] Re-registering framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.530449 30614 hierarchical.hpp:321] Added framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.530490 30614 hierarchical.hpp:834] No resources available to
> allocate!
> I0224 23:22:32.530510 30614 hierarchical.hpp:741] Performed allocation for 0
> slaves in 32479ns
> I0224 23:22:32.530743 30618 master.cpp:1764] Re-registering framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.530777 30611 sched.cpp:448] Framework registered with
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.530787 30618 master.cpp:1804] Allowing framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391 to
> re-register with an already used id
> I0224 23:22:32.530824 30611 sched.cpp:462] Scheduler::registered took 20697ns
> I0224 23:22:32.530948 30605 sched.cpp:477] Ignoring framework re-registered
> message because the driver is already connected!
> I0224 23:22:32.533220 30606 status_update_manager.cpp:171] Pausing sending
> status updates
> I0224 23:22:32.533226 30605 slave.cpp:624] New master detected at
> [email protected]:38391
> I0224 23:22:32.533362 30605 slave.cpp:687] Authenticating with master
> [email protected]:38391
> I0224 23:22:32.533385 30605 slave.cpp:692] Using default CRAM-MD5
> authenticatee
> I0224 23:22:32.533529 30605 slave.cpp:660] Detecting new master
> I0224 23:22:32.533576 30612 authenticatee.hpp:139] Creating new client SASL
> connection
> I0224 23:22:32.533759 30603 master.cpp:3813] Authenticating
> slave(66)@67.195.81.187:38391
> I0224 23:22:32.533790 30603 master.cpp:3824] Using default CRAM-MD5
> authenticator
> I0224 23:22:32.534018 30605 authenticator.hpp:170] Creating new server SASL
> connection
> I0224 23:22:32.534195 30609 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0224 23:22:32.534227 30609 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0224 23:22:32.534339 30609 authenticator.hpp:276] Received SASL
> authentication start
> I0224 23:22:32.534394 30609 authenticator.hpp:398] Authentication requires
> more steps
> I0224 23:22:32.534494 30609 authenticatee.hpp:276] Received SASL
> authentication step
> I0224 23:22:32.534600 30609 authenticator.hpp:304] Received SASL
> authentication step
> I0224 23:22:32.534629 30609 auxprop.cpp:99] 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
> I0224 23:22:32.534642 30609 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0224 23:22:32.534692 30609 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0224 23:22:32.534725 30609 auxprop.cpp:99] 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
> I0224 23:22:32.534740 30609 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.534749 30609 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0224 23:22:32.534765 30609 authenticator.hpp:390] Authentication success
> I0224 23:22:32.534891 30604 authenticatee.hpp:316] Authentication success
> I0224 23:22:32.534906 30609 master.cpp:3871] Successfully authenticated
> principal 'test-principal' at slave(66)@67.195.81.187:38391
> I0224 23:22:32.535146 30608 slave.cpp:758] Successfully authenticated with
> master [email protected]:38391
> I0224 23:22:32.535567 30608 slave.cpp:1090] Will retry registration in
> 10.96399ms if necessary
> I0224 23:22:32.535843 30610 master.cpp:3120] Re-registering slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.536542 30606 registrar.cpp:445] Applied 1 operations in
> 71981ns; attempting to update the 'registry'
> I0224 23:22:32.539535 30612 log.cpp:684] Attempting to append 316 bytes to
> the log
> I0224 23:22:32.539682 30617 coordinator.cpp:340] Coordinator attempting to
> write 2 action at position 7
> I0224 23:22:32.540549 30608 replica.cpp:511] Replica received write request
> for position 7
> I0224 23:22:32.540832 30608 leveldb.cpp:343] Persisting action (335 bytes) to
> leveldb took 249089ns
> I0224 23:22:32.540858 30608 replica.cpp:679] Persisted action at 7
> I0224 23:22:32.541555 30604 replica.cpp:658] Replica received learned notice
> for position 7
> I0224 23:22:32.542254 30604 leveldb.cpp:343] Persisting action (337 bytes) to
> leveldb took 671501ns
> I0224 23:22:32.542294 30604 replica.cpp:679] Persisted action at 7
> I0224 23:22:32.542320 30604 replica.cpp:664] Replica learned 2 action at
> position 7
> I0224 23:22:32.543231 30603 registrar.cpp:490] Successfully updated the
> 'registry' in 6.617088ms
> I0224 23:22:32.543637 30613 log.cpp:703] Attempting to truncate the log to 7
> I0224 23:22:32.543784 30611 coordinator.cpp:340] Coordinator attempting to
> write 3 action at position 8
> I0224 23:22:32.544088 30610 master.hpp:822] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 20150224-232231-3142697795-38391-30589-S0
> (pomona.apache.org)
> I0224 23:22:32.544503 30612 slave.cpp:2831] Received ping from
> slave-observer(67)@67.195.81.187:38391
> I0224 23:22:32.544530 30618 replica.cpp:511] Replica received write request
> for position 8
> I0224 23:22:32.544800 30610 master.cpp:3191] Re-registered slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0224 23:22:32.544862 30607 slave.cpp:860] Re-registered with master
> [email protected]:38391
> I0224 23:22:32.544961 30606 status_update_manager.cpp:178] Resuming sending
> status updates
> I0224 23:22:32.544975 30610 master.cpp:3219] Sending updated checkpointed
> resources to slave 20150224-232231-3142697795-38391-30589-S0 at
> slave(66)@67.195.81.187:38391 (pomona.apache.org)
> I0224 23:22:32.545047 30612 hierarchical.hpp:455] Added slave
> 20150224-232231-3142697795-38391-30589-S0 (pomona.apache.org) with cpus(*):2;
> mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):1;
> mem(*):524; disk(*):3.70122e+06; ports(*):[31000-32000] available)
> I0224 23:22:32.545090 30603 slave.cpp:1922] Updating framework
> 20150224-232231-3142697795-38391-30589-0000 pid to
> [email protected]:38391
> I0224 23:22:32.545128 30618 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 567893ns
> I0224 23:22:32.545155 30618 replica.cpp:679] Persisted action at 8
> I0224 23:22:32.545240 30613 status_update_manager.cpp:178] Resuming sending
> status updates
> I0224 23:22:32.545424 30603 slave.cpp:2010] Updated checkpointed resources
> from to
> I0224 23:22:32.545569 30612 hierarchical.hpp:759] Performed allocation for
> slave 20150224-232231-3142697795-38391-30589-S0 in 472208ns
> I0224 23:22:32.545915 30610 replica.cpp:658] Replica received learned notice
> for position 8
> I0224 23:22:32.545930 30607 master.cpp:3755] Sending 1 offers to framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.688380 30615 hierarchical.hpp:741] Performed allocation for 1
> slaves in 418073ns
> I0224 23:22:32.691712 30607 master.cpp:3755] Sending 1 offers to framework
> 20150224-232231-3142697795-38391-30589-0000 (default) at
> [email protected]:38391
> I0224 23:22:32.691795 30605 sched.cpp:611] Scheduler::resourceOffers took
> 95977ns
> I0224 23:22:32.691961 30610 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 649479ns
> I0224 23:22:32.692033 30610 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 43354ns
> I0224 23:22:32.692061 30610 replica.cpp:679] Persisted action at 8
> I0224 23:22:32.692093 30610 replica.cpp:664] Replica learned 3 action at
> position 8
> I0224 23:22:32.692191 30589 sched.cpp:1589] Asked to stop the driver
> ../../src/tests/master_allocator_tests.cpp:1308: Failure
> Mock function called more times than expected - returning directly.
> Function call: resourceOffers(0x7fff88bc3d10, @0x2b8726c54b30 { 128-byte
> object <D0-C4 A2-22 87-2B 00-00 00-00 00-00 00-00 00-00 E0-C2 00-3C 87-2B
> 00-00 60-C3 00-3C 87-2B 00-00 E0-C3 00-3C 87-2B 00-00 D0-C0 00-3C 87-2B 00-00
> 50-7B 00-3C 87-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 20-69 73-20 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 20-6E 65-76 50-C2 00-3C
> 87-2B 00-00 01-00 00-00 01-00 00-00 04-00 00-00 00-00 00-00 00-00 00-00 0F-00
> 00-00> })
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0224 23:22:32.692252 30605 sched.cpp:611] Scheduler::resourceOffers took
> 213312ns
> I0224 23:22:32.692296 30610 master.cpp:787] Master terminating
> I0224 23:22:32.692387 30605 sched.cpp:831] Stopping framework
> '20150224-232231-3142697795-38391-30589-0000'
> W0224 23:22:32.692448 30610 master.cpp:4668] Removing task 0 with resources
> cpus(*):1; mem(*):500 of framework
> 20150224-232231-3142697795-38391-30589-0000 on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org) in non-terminal state TASK_RUNNING
> I0224 23:22:32.692739 30613 hierarchical.hpp:648] Recovered cpus(*):1;
> mem(*):500 (total allocatable: cpus(*):1; mem(*):500) on slave
> 20150224-232231-3142697795-38391-30589-S0 from framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.692939 30610 master.cpp:4711] Removing executor 'default' with
> resources of framework 20150224-232231-3142697795-38391-30589-0000 on slave
> 20150224-232231-3142697795-38391-30589-S0 at slave(66)@67.195.81.187:38391
> (pomona.apache.org)
> I0224 23:22:32.693953 30610 slave.cpp:2916] [email protected]:38391 exited
> W0224 23:22:32.693982 30610 slave.cpp:2919] Master disconnected! Waiting for
> a new master to be elected
> I0224 23:22:32.695185 30589 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.695327 30589 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.697404 30613 slave.cpp:3191] Executor 'default' of framework
> 20150224-232231-3142697795-38391-30589-0000 exited with status 0
> I0224 23:22:32.699574 30613 slave.cpp:2508] Handling status update TASK_LOST
> (UUID: d33cdd1e-5586-4ae5-94b0-870a1443844b) for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000 from @0.0.0.0:0
> I0224 23:22:32.699658 30613 slave.cpp:4486] Terminating task 0
> I0224 23:22:32.699964 30613 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.700003 30613 slave.cpp:506] Slave terminating
> I0224 23:22:32.700073 30613 slave.cpp:1745] Asked to shut down framework
> 20150224-232231-3142697795-38391-30589-0000 by @0.0.0.0:0
> I0224 23:22:32.700098 30613 slave.cpp:1770] Shutting down framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.700160 30613 slave.cpp:3300] Cleaning up executor 'default' of
> framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.700355 30610 gc.cpp:56] Scheduling
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default/runs/7c203619-b40f-4d0a-9b75-9ddeecb63472'
> for gc 6.99999189524148days in the future
> I0224 23:22:32.700449 30613 slave.cpp:3379] Cleaning up framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.700522 30610 gc.cpp:56] Scheduling
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000/executors/default'
> for gc 6.99999189365926days in the future
> I0224 23:22:32.700580 30608 status_update_manager.cpp:279] Closing status
> update streams for framework 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.700630 30610 gc.cpp:56] Scheduling
> '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_ikVXQM/slaves/20150224-232231-3142697795-38391-30589-S0/frameworks/20150224-232231-3142697795-38391-30589-0000'
> for gc 6.99999189199111days in the future
> I0224 23:22:32.700666 30608 status_update_manager.cpp:525] Cleaning up status
> update stream for task 0 of framework
> 20150224-232231-3142697795-38391-30589-0000
> I0224 23:22:32.702638 30589 process.cpp:2117] Dropped / Lost event for PID:
> [email protected]:38391
> I0224 23:22:32.702955 30589 process.cpp:2117] Dropped / Lost event for PID:
> slave(66)@67.195.81.187:38391
> [ FAILED ] MasterAllocatorTest/0.FrameworkReregistersFirst, where TypeParam
> =
> mesos::internal::master::allocator::MesosAllocator<mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter,
> mesos::internal::master::allocator::DRFSorter> > (1027 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
