[
https://issues.apache.org/jira/browse/MESOS-1844?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vinod Kone updated MESOS-1844:
------------------------------
Story Points: 1 (was: 2)
https://reviews.apache.org/r/26163/
> AllocatorTest/0.SlaveLost is flaky
> ----------------------------------
>
> Key: MESOS-1844
> URL: https://issues.apache.org/jira/browse/MESOS-1844
> Project: Mesos
> Issue Type: Bug
> Components: test
> Environment: Fedora 20. GCC
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> {code}
> [ RUN ] AllocatorTest/0.SlaveLost
> Using temporary directory '/tmp/AllocatorTest_0_SlaveLost_Z2oazw'
> I0929 16:58:29.484141 3486 leveldb.cpp:176] Opened db in 604109ns
> I0929 16:58:29.484629 3486 leveldb.cpp:183] Compacted db in 172697ns
> I0929 16:58:29.484912 3486 leveldb.cpp:198] Created db iterator in 6429ns
> I0929 16:58:29.485133 3486 leveldb.cpp:204] Seeked to beginning of db in
> 1618ns
> I0929 16:58:29.485337 3486 leveldb.cpp:273] Iterated through 0 keys in the
> db in 752ns
> I0929 16:58:29.485595 3486 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0929 16:58:29.486017 3500 recover.cpp:425] Starting replica recovery
> I0929 16:58:29.486304 3500 recover.cpp:451] Replica is in EMPTY status
> I0929 16:58:29.486793 3500 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I0929 16:58:29.487205 3500 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I0929 16:58:29.487540 3500 recover.cpp:542] Updating replica status to
> STARTING
> I0929 16:58:29.487911 3500 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 36629ns
> I0929 16:58:29.488173 3500 replica.cpp:320] Persisted replica status to
> STARTING
> I0929 16:58:29.488438 3500 recover.cpp:451] Replica is in STARTING status
> I0929 16:58:29.488891 3500 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0929 16:58:29.489187 3500 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I0929 16:58:29.489516 3500 recover.cpp:542] Updating replica status to VOTING
> I0929 16:58:29.489887 3502 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 32099ns
> I0929 16:58:29.490124 3502 replica.cpp:320] Persisted replica status to
> VOTING
> I0929 16:58:29.490381 3500 recover.cpp:556] Successfully joined the Paxos
> group
> I0929 16:58:29.490713 3500 recover.cpp:440] Recover process terminated
> I0929 16:58:29.493401 3506 master.cpp:312] Master
> 20140929-165829-2759502016-55618-3486 (fedora-20) started on
> 192.168.122.164:55618
> I0929 16:58:29.493700 3506 master.cpp:358] Master only allowing
> authenticated frameworks to register
> I0929 16:58:29.493921 3506 master.cpp:363] Master only allowing
> authenticated slaves to register
> I0929 16:58:29.494123 3506 credentials.hpp:36] Loading credentials for
> authentication from '/tmp/AllocatorTest_0_SlaveLost_Z2oazw/credentials'
> I0929 16:58:29.494500 3506 master.cpp:392] Authorization enabled
> I0929 16:58:29.495249 3506 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I0929 16:58:29.495728 3502 hierarchical_allocator_process.hpp:299]
> Initializing hierarchical allocator process with master :
> [email protected]:55618
> I0929 16:58:29.496196 3506 master.cpp:1241] The newly elected leader is
> [email protected]:55618 with id 20140929-165829-2759502016-55618-3486
> I0929 16:58:29.496469 3506 master.cpp:1254] Elected as the leading master!
> I0929 16:58:29.496713 3506 master.cpp:1072] Recovering from registrar
> I0929 16:58:29.497020 3506 registrar.cpp:312] Recovering registrar
> I0929 16:58:29.497486 3506 log.cpp:656] Attempting to start the writer
> I0929 16:58:29.498105 3506 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0929 16:58:29.498373 3506 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 27145ns
> I0929 16:58:29.498605 3506 replica.cpp:342] Persisted promised to 1
> I0929 16:58:29.500880 3500 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0929 16:58:29.501404 3500 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0929 16:58:29.501687 3500 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 57971ns
> I0929 16:58:29.501935 3500 replica.cpp:676] Persisted action at 0
> I0929 16:58:29.504905 3507 replica.cpp:508] Replica received write request
> for position 0
> I0929 16:58:29.505130 3507 leveldb.cpp:438] Reading position from leveldb
> took 18418ns
> I0929 16:58:29.505377 3507 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 19998ns
> I0929 16:58:29.505571 3507 replica.cpp:676] Persisted action at 0
> I0929 16:58:29.505957 3507 replica.cpp:655] Replica received learned notice
> for position 0
> I0929 16:58:29.506186 3507 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 21648ns
> I0929 16:58:29.506433 3507 replica.cpp:676] Persisted action at 0
> I0929 16:58:29.506767 3507 replica.cpp:661] Replica learned NOP action at
> position 0
> I0929 16:58:29.507199 3507 log.cpp:672] Writer started with ending position 0
> I0929 16:58:29.507730 3507 leveldb.cpp:438] Reading position from leveldb
> took 11532ns
> I0929 16:58:29.508915 3507 registrar.cpp:345] Successfully fetched the
> registry (0B)
> I0929 16:58:29.509230 3507 registrar.cpp:421] Attempting to update the
> 'registry'
> I0929 16:58:29.510516 3500 log.cpp:680] Attempting to append 130 bytes to
> the log
> I0929 16:58:29.510949 3500 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0929 16:58:29.511363 3500 replica.cpp:508] Replica received write request
> for position 1
> I0929 16:58:29.511697 3500 leveldb.cpp:343] Persisting action (149 bytes) to
> leveldb took 66530ns
> I0929 16:58:29.512039 3500 replica.cpp:676] Persisted action at 1
> I0929 16:58:29.512460 3500 replica.cpp:655] Replica received learned notice
> for position 1
> I0929 16:58:29.512778 3500 leveldb.cpp:343] Persisting action (151 bytes) to
> leveldb took 24121ns
> I0929 16:58:29.513013 3500 replica.cpp:676] Persisted action at 1
> I0929 16:58:29.513239 3500 replica.cpp:661] Replica learned APPEND action at
> position 1
> I0929 16:58:29.513674 3500 log.cpp:699] Attempting to truncate the log to 1
> I0929 16:58:29.513954 3500 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0929 16:58:29.514385 3500 replica.cpp:508] Replica received write request
> for position 2
> I0929 16:58:29.514680 3500 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 65014ns
> I0929 16:58:29.514991 3500 replica.cpp:676] Persisted action at 2
> I0929 16:58:29.516978 3501 replica.cpp:655] Replica received learned notice
> for position 2
> I0929 16:58:29.517319 3501 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 24103ns
> I0929 16:58:29.517546 3501 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 16533ns
> I0929 16:58:29.517801 3501 replica.cpp:676] Persisted action at 2
> I0929 16:58:29.518039 3501 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I0929 16:58:29.518539 3507 registrar.cpp:478] Successfully updated 'registry'
> I0929 16:58:29.518885 3507 registrar.cpp:371] Successfully recovered
> registrar
> I0929 16:58:29.519201 3507 master.cpp:1099] Recovered 0 slaves from the
> Registry (94B) ; allowing 10mins for slaves to re-register
> I0929 16:58:29.533073 3505 slave.cpp:169] Slave started on
> 57)@192.168.122.164:55618
> I0929 16:58:29.533500 3505 credentials.hpp:84] Loading credential for
> authentication from '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/credential'
> I0929 16:58:29.533834 3505 slave.cpp:276] Slave using credential for:
> test-principal
> I0929 16:58:29.534168 3505 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):752; ports(*):[31000-32000]
> I0929 16:58:29.534751 3505 slave.cpp:317] Slave hostname: fedora-20
> I0929 16:58:29.534965 3505 slave.cpp:318] Slave checkpoint: false
> I0929 16:58:29.535557 3505 state.cpp:33] Recovering state from
> '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/meta'
> I0929 16:58:29.535951 3505 status_update_manager.cpp:193] Recovering status
> update manager
> I0929 16:58:29.536290 3505 slave.cpp:3271] Finished recovery
> I0929 16:58:29.536782 3505 slave.cpp:598] New master detected at
> [email protected]:55618
> I0929 16:58:29.537122 3505 slave.cpp:672] Authenticating with master
> [email protected]:55618
> I0929 16:58:29.537492 3505 slave.cpp:645] Detecting new master
> I0929 16:58:29.537294 3506 status_update_manager.cpp:167] New master
> detected at [email protected]:55618
> I0929 16:58:29.537642 3507 authenticatee.hpp:128] Creating new client SASL
> connection
> I0929 16:58:29.538769 3502 master.cpp:3737] Authenticating
> slave(57)@192.168.122.164:55618
> I0929 16:58:29.539091 3502 authenticator.hpp:156] Creating new server SASL
> connection
> I0929 16:58:29.539710 3503 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0929 16:58:29.539943 3503 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0929 16:58:29.540206 3502 authenticator.hpp:262] Received SASL
> authentication start
> I0929 16:58:29.540457 3502 authenticator.hpp:384] Authentication requires
> more steps
> I0929 16:58:29.540757 3502 authenticatee.hpp:265] Received SASL
> authentication step
> I0929 16:58:29.541121 3502 authenticator.hpp:290] Received SASL
> authentication step
> I0929 16:58:29.541368 3502 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0929 16:58:29.541599 3502 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0929 16:58:29.541874 3502 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0929 16:58:29.542129 3502 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0929 16:58:29.542333 3502 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.542553 3502 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.542785 3502 authenticator.hpp:376] Authentication success
> I0929 16:58:29.543047 3502 authenticatee.hpp:305] Authentication success
> I0929 16:58:29.543381 3502 slave.cpp:729] Successfully authenticated with
> master [email protected]:55618
> I0929 16:58:29.543707 3502 slave.cpp:992] Will retry registration in
> 11.795692ms if necessary
> I0929 16:58:29.543179 3503 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(57)@192.168.122.164:55618
> I0929 16:58:29.544255 3503 master.cpp:2930] Registering slave at
> slave(57)@192.168.122.164:55618 (fedora-20) with id
> 20140929-165829-2759502016-55618-3486-0
> I0929 16:58:29.544587 3503 registrar.cpp:421] Attempting to update the
> 'registry'
> I0929 16:58:29.545816 3500 log.cpp:680] Attempting to append 299 bytes to
> the log
> I0929 16:58:29.546267 3500 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0929 16:58:29.546749 3500 replica.cpp:508] Replica received write request
> for position 3
> I0929 16:58:29.547030 3500 leveldb.cpp:343] Persisting action (318 bytes) to
> leveldb took 31759ns
> I0929 16:58:29.547236 3500 replica.cpp:676] Persisted action at 3
> I0929 16:58:29.548902 3506 replica.cpp:655] Replica received learned notice
> for position 3
> I0929 16:58:29.549139 3506 leveldb.cpp:343] Persisting action (320 bytes) to
> leveldb took 25595ns
> I0929 16:58:29.549343 3506 replica.cpp:676] Persisted action at 3
> I0929 16:58:29.549607 3506 replica.cpp:661] Replica learned APPEND action at
> position 3
> I0929 16:58:29.550081 3506 log.cpp:699] Attempting to truncate the log to 3
> I0929 16:58:29.550497 3506 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0929 16:58:29.550943 3506 replica.cpp:508] Replica received write request
> for position 4
> I0929 16:58:29.551198 3506 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 20852ns
> I0929 16:58:29.551409 3506 replica.cpp:676] Persisted action at 4
> I0929 16:58:29.551795 3506 replica.cpp:655] Replica received learned notice
> for position 4
> I0929 16:58:29.552094 3506 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 22182ns
> I0929 16:58:29.552320 3506 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 18503ns
> I0929 16:58:29.552525 3506 replica.cpp:676] Persisted action at 4
> I0929 16:58:29.552781 3506 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> I0929 16:58:29.550289 3503 registrar.cpp:478] Successfully updated 'registry'
> I0929 16:58:29.553553 3503 master.cpp:2970] Registered slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20)
> I0929 16:58:29.553807 3503 master.cpp:4180] Adding slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20) with cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]
> I0929 16:58:29.554152 3503 slave.cpp:763] Registered with master
> [email protected]:55618; given slave ID
> 20140929-165829-2759502016-55618-3486-0
> I0929 16:58:29.554455 3503 slave.cpp:2345] Received ping from
> slave-observer(56)@192.168.122.164:55618
> I0929 16:58:29.554707 3504 hierarchical_allocator_process.hpp:442] Added
> slave 20140929-165829-2759502016-55618-3486-0 (fedora-20) with cpus(*):2;
> mem(*):1024; disk(*):752; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024;
> disk(*):752; ports(*):[31000-32000] available)
> I0929 16:58:29.555064 3504 hierarchical_allocator_process.hpp:679] Performed
> allocation for slave 20140929-165829-2759502016-55618-3486-0 in 13111ns
> I0929 16:58:29.558220 3486 sched.cpp:137] Version: 0.21.0
> I0929 16:58:29.558821 3501 sched.cpp:233] New master detected at
> [email protected]:55618
> I0929 16:58:29.559054 3501 sched.cpp:283] Authenticating with master
> [email protected]:55618
> I0929 16:58:29.559360 3501 authenticatee.hpp:128] Creating new client SASL
> connection
> I0929 16:58:29.560096 3501 master.cpp:3737] Authenticating
> [email protected]:55618
> I0929 16:58:29.560430 3501 authenticator.hpp:156] Creating new server SASL
> connection
> I0929 16:58:29.561141 3501 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0929 16:58:29.561465 3501 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0929 16:58:29.561743 3501 authenticator.hpp:262] Received SASL
> authentication start
> I0929 16:58:29.562098 3501 authenticator.hpp:384] Authentication requires
> more steps
> I0929 16:58:29.562353 3501 authenticatee.hpp:265] Received SASL
> authentication step
> I0929 16:58:29.562721 3507 authenticator.hpp:290] Received SASL
> authentication step
> I0929 16:58:29.563022 3507 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0929 16:58:29.563254 3507 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0929 16:58:29.563484 3507 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0929 16:58:29.563736 3507 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0929 16:58:29.563976 3507 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.564188 3507 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.564415 3507 authenticator.hpp:376] Authentication success
> I0929 16:58:29.564673 3507 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at
> [email protected]:55618
> I0929 16:58:29.568681 3501 authenticatee.hpp:305] Authentication success
> I0929 16:58:29.569046 3501 sched.cpp:357] Successfully authenticated with
> master [email protected]:55618
> I0929 16:58:29.569286 3501 sched.cpp:476] Sending registration request to
> [email protected]:55618
> I0929 16:58:29.569581 3507 master.cpp:1360] Received registration request
> from [email protected]:55618
> I0929 16:58:29.569846 3507 master.cpp:1320] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0929 16:58:29.570219 3507 master.cpp:1419] Registering framework
> 20140929-165829-2759502016-55618-3486-0000 at
> [email protected]:55618
> I0929 16:58:29.570543 3506 sched.cpp:407] Framework registered with
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.570811 3506 sched.cpp:421] Scheduler::registered took 13811ns
> I0929 16:58:29.571135 3502 hierarchical_allocator_process.hpp:329] Added
> framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.571393 3502 hierarchical_allocator_process.hpp:734] Offering
> cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-0 to framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.571723 3502 hierarchical_allocator_process.hpp:659] Performed
> allocation for 1 slaves in 368547ns
> I0929 16:58:29.572125 3507 master.hpp:868] Adding offer
> 20140929-165829-2759502016-55618-3486-0 with resources cpus(*):2;
> mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-0 (fedora-20)
> I0929 16:58:29.572374 3507 master.cpp:3679] Sending 1 offers to framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.572841 3503 sched.cpp:544] Scheduler::resourceOffers took
> 114306ns
> I0929 16:58:29.573197 3507 master.hpp:877] Removing offer
> 20140929-165829-2759502016-55618-3486-0 with resources cpus(*):2;
> mem(*):1024; disk(*):752; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-0 (fedora-20)
> I0929 16:58:29.573457 3507 master.cpp:2274] Processing reply for offers: [
> 20140929-165829-2759502016-55618-3486-0 ] on slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20) for framework 20140929-165829-2759502016-55618-3486-0000
> W0929 16:58:29.573717 3507 master.cpp:1944] 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.
> W0929 16:58:29.573953 3507 master.cpp:1955] 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.
> I0929 16:58:29.574177 3507 master.cpp:2357] Authorizing framework principal
> 'test-principal' to launch task 0 as user 'jenkins'
> I0929 16:58:29.574745 3507 master.hpp:845] Adding task 0 with resources
> cpus(*):2; mem(*):512 on slave 20140929-165829-2759502016-55618-3486-0
> (fedora-20)
> I0929 16:58:29.574992 3507 master.cpp:2423] Launching task 0 of framework
> 20140929-165829-2759502016-55618-3486-0000 with resources cpus(*):2;
> mem(*):512 on slave 20140929-165829-2759502016-55618-3486-0 at
> slave(57)@192.168.122.164:55618 (fedora-20)
> I0929 16:58:29.575315 3503 slave.cpp:1023] Got assigned task 0 for framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.575724 3503 slave.cpp:1133] Launching task 0 for framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.578129 3503 exec.cpp:132] Version: 0.21.0
> I0929 16:58:29.578505 3504 exec.cpp:182] Executor started at:
> executor(30)@192.168.122.164:55618 with pid 3486
> I0929 16:58:29.578867 3503 slave.cpp:1246] Queuing task '0' for executor
> default of framework '20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.579144 3503 slave.cpp:554] Successfully attached file
> '/tmp/AllocatorTest_0_SlaveLost_xdXHfg/slaves/20140929-165829-2759502016-55618-3486-0/frameworks/20140929-165829-2759502016-55618-3486-0000/executors/default/runs/b0de9759-7054-4763-90f4-889ddc3a8524'
> I0929 16:58:29.579401 3503 slave.cpp:1756] Got registration for executor
> 'default' of framework 20140929-165829-2759502016-55618-3486-0000 from
> executor(30)@192.168.122.164:55618
> I0929 16:58:29.579879 3506 exec.cpp:206] Executor registered on slave
> 20140929-165829-2759502016-55618-3486-0
> I0929 16:58:29.580921 3506 exec.cpp:218] Executor::registered took 17644ns
> I0929 16:58:29.581188 3503 slave.cpp:1875] Flushing queued task 0 for
> executor 'default' of framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.581526 3504 exec.cpp:293] Executor asked to run task '0'
> I0929 16:58:29.581807 3504 exec.cpp:302] Executor::launchTask took 42649ns
> I0929 16:58:29.583133 3504 exec.cpp:525] Executor sending status update
> TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of
> framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.586869 3503 slave.cpp:2611] Monitoring executor 'default' of
> framework '20140929-165829-2759502016-55618-3486-0000' in container
> 'b0de9759-7054-4763-90f4-889ddc3a8524'
> I0929 16:58:29.587252 3503 slave.cpp:2109] Handling status update
> TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of
> framework 20140929-165829-2759502016-55618-3486-0000 from
> executor(30)@192.168.122.164:55618
> I0929 16:58:29.587723 3502 hierarchical_allocator_process.hpp:563] Recovered
> mem(*):512; disk(*):752; ports(*):[31000-32000] (total allocatable:
> mem(*):512; disk(*):752; ports(*):[31000-32000]) on slave
> 20140929-165829-2759502016-55618-3486-0 from framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.588127 3502 hierarchical_allocator_process.hpp:599] Framework
> 20140929-165829-2759502016-55618-3486-0000 filtered slave
> 20140929-165829-2759502016-55618-3486-0 for 5secs
> I0929 16:58:29.588433 3506 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0
> of framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.588767 3506 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 0 of framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.589054 3506 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0
> of framework 20140929-165829-2759502016-55618-3486-0000 to
> [email protected]:55618
> I0929 16:58:29.589400 3506 master.cpp:3301] Forwarding status update
> TASK_RUNNING (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of
> framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.589702 3506 master.cpp:3273] Status update TASK_RUNNING
> (UUID: 454bdb88-fd27-4201-b2c7-4ea03a6d00b3) for task 0 of framework
> 20140929-165829-2759502016-55618-3486-0000 from slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20)
> I0929 16:58:29.589923 3500 sched.cpp:635] Scheduler::statusUpdate took
> 36034ns
> I0929 16:58:29.590337 3500 master.cpp:2777] Forwarding status update
> acknowledgement 454bdb88-fd27-4201-b2c7-4ea03a6d00b3 for task 0 of framework
> 20140929-165829-2759502016-55618-3486-0000 to slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20)
> I0929 16:58:29.590643 3503 slave.cpp:477] Slave terminating
> I0929 16:58:29.590893 3503 slave.cpp:1429] Asked to shut down framework
> 20140929-165829-2759502016-55618-3486-0000 by @0.0.0.0:0
> I0929 16:58:29.591136 3503 slave.cpp:1454] Shutting down framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.591367 3503 slave.cpp:2951] Shutting down executor 'default'
> of framework 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.591701 3501 master.cpp:817] Slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20) disconnected
> I0929 16:58:29.591917 3501 master.cpp:821] Removing disconnected slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20) because it is not checkpointing!
> I0929 16:58:29.592149 3501 master.cpp:4301] Removing slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20)
> I0929 16:58:29.593868 3505 hierarchical_allocator_process.hpp:467] Removed
> slave 20140929-165829-2759502016-55618-3486-0
> I0929 16:58:29.594907 3486 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I0929 16:58:29.595091 3501 master.cpp:4485] Removing task 0 with resources
> cpus(*):2; mem(*):512 of framework 20140929-165829-2759502016-55618-3486-0000
> on slave 20140929-165829-2759502016-55618-3486-0 at
> slave(57)@192.168.122.164:55618 (fedora-20)
> I0929 16:58:29.595960 3501 master.cpp:4514] Removing executor 'default' with
> resources of framework 20140929-165829-2759502016-55618-3486-0000 on slave
> 20140929-165829-2759502016-55618-3486-0 at slave(57)@192.168.122.164:55618
> (fedora-20)
> tests/allocator_tests.cpp:1552: Failure
> Mock function called more times than expected - taking default action
> specified at:
> ./tests/mesos.hpp:616:
> Function call: resourcesRecovered(@0x7f958007f590
> 20140929-165829-2759502016-55618-3486-0000, @0x7f958007f5b0
> 20140929-165829-2759502016-55618-3486-0, @0x7f958007f5d0 {}, @0x7f958007f5e8
> 16-byte object <01-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>)
> Expected: to be called twice
> I0929 16:58:29.596640 3506 registrar.cpp:421] Attempting to update the
> 'registry'
> Actual: called 3 times - over-saturated and active
> I0929 16:58:29.598697 3506 log.cpp:680] Attempting to append 133 bytes to
> the log
> I0929 16:58:29.598984 3500 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 5
> I0929 16:58:29.599422 3500 replica.cpp:508] Replica received write request
> for position 5
> I0929 16:58:29.599712 3500 leveldb.cpp:343] Persisting action (152 bytes) to
> leveldb took 65914ns
> I0929 16:58:29.599931 3500 replica.cpp:676] Persisted action at 5
> I0929 16:58:29.600332 3500 replica.cpp:655] Replica received learned notice
> for position 5
> I0929 16:58:29.600621 3500 leveldb.cpp:343] Persisting action (154 bytes) to
> leveldb took 24641ns
> I0929 16:58:29.600858 3500 replica.cpp:676] Persisted action at 5
> I0929 16:58:29.601060 3500 replica.cpp:661] Replica learned APPEND action at
> position 5
> I0929 16:58:29.601588 3506 registrar.cpp:478] Successfully updated 'registry'
> I0929 16:58:29.601765 3500 log.cpp:699] Attempting to truncate the log to 5
> I0929 16:58:29.602308 3501 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 6
> I0929 16:58:29.602736 3505 replica.cpp:508] Replica received write request
> for position 6
> I0929 16:58:29.602967 3505 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 22681ns
> I0929 16:58:29.603175 3505 replica.cpp:676] Persisted action at 6
> I0929 16:58:29.603591 3501 replica.cpp:655] Replica received learned notice
> for position 6
> I0929 16:58:29.603903 3501 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 23564ns
> I0929 16:58:29.604161 3501 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 18683ns
> I0929 16:58:29.604378 3501 replica.cpp:676] Persisted action at 6
> I0929 16:58:29.604575 3501 replica.cpp:661] Replica learned TRUNCATE action
> at position 6
> I0929 16:58:29.604970 3502 master.cpp:4393] Removed slave
> 20140929-165829-2759502016-55618-3486-0 (fedora-20)
> I0929 16:58:29.605197 3502 master.cpp:3296] Sending status update TASK_LOST
> (UUID: cfc350bc-4ebf-4ea1-9fe4-27f53825c787) for task 0 of framework
> 20140929-165829-2759502016-55618-3486-0000 'Slave fedora-20 removed'
> I0929 16:58:29.605445 3502 master.cpp:4411] Notifying framework
> 20140929-165829-2759502016-55618-3486-0000 of lost slave
> 20140929-165829-2759502016-55618-3486-0 (fedora-20) after recovering
> I0929 16:58:29.605756 3502 sched.cpp:635] Scheduler::statusUpdate took 9369ns
> I0929 16:58:29.605996 3502 sched.cpp:686] Lost slave
> 20140929-165829-2759502016-55618-3486-0
> I0929 16:58:29.606210 3502 sched.cpp:697] Scheduler::slaveLost took 13761ns
> I0929 16:58:29.607326 3501 slave.cpp:169] Slave started on
> 58)@192.168.122.164:55618
> I0929 16:58:29.607640 3501 credentials.hpp:84] Loading credential for
> authentication from '/tmp/AllocatorTest_0_SlaveLost_NcoJ6Z/credential'
> I0929 16:58:29.607975 3501 slave.cpp:276] Slave using credential for:
> test-principal
> I0929 16:58:29.608253 3501 slave.cpp:289] Slave resources: cpus(*):3;
> mem(*):256; disk(*):1024; ports(*):[31000-32000]
> I0929 16:58:29.608832 3501 slave.cpp:317] Slave hostname: fedora-20
> I0929 16:58:29.608989 3501 slave.cpp:318] Slave checkpoint: false
> I0929 16:58:29.609542 3501 state.cpp:33] Recovering state from
> '/tmp/AllocatorTest_0_SlaveLost_NcoJ6Z/meta'
> I0929 16:58:29.609904 3500 status_update_manager.cpp:193] Recovering status
> update manager
> I0929 16:58:29.610119 3500 containerizer.cpp:252] Recovering containerizer
> I0929 16:58:29.610589 3507 slave.cpp:3271] Finished recovery
> I0929 16:58:29.611037 3507 slave.cpp:598] New master detected at
> [email protected]:55618
> I0929 16:58:29.611264 3507 slave.cpp:672] Authenticating with master
> [email protected]:55618
> I0929 16:58:29.611529 3507 slave.cpp:645] Detecting new master
> I0929 16:58:29.611385 3506 status_update_manager.cpp:167] New master
> detected at [email protected]:55618
> I0929 16:58:29.611719 3503 authenticatee.hpp:128] Creating new client SASL
> connection
> I0929 16:58:29.612570 3503 master.cpp:3737] Authenticating
> slave(58)@192.168.122.164:55618
> I0929 16:58:29.612843 3503 authenticator.hpp:156] Creating new server SASL
> connection
> I0929 16:58:29.613394 3503 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0929 16:58:29.613706 3503 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0929 16:58:29.614083 3503 authenticator.hpp:262] Received SASL
> authentication start
> I0929 16:58:29.614326 3503 authenticator.hpp:384] Authentication requires
> more steps
> I0929 16:58:29.614552 3503 authenticatee.hpp:265] Received SASL
> authentication step
> I0929 16:58:29.614828 3503 authenticator.hpp:290] Received SASL
> authentication step
> I0929 16:58:29.615067 3503 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0929 16:58:29.615314 3503 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0929 16:58:29.615562 3503 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0929 16:58:29.615766 3503 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0929 16:58:29.616060 3503 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.616387 3503 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0929 16:58:29.616631 3503 authenticator.hpp:376] Authentication success
> I0929 16:58:29.616929 3503 authenticatee.hpp:305] Authentication success
> I0929 16:58:29.617081 3501 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(58)@192.168.122.164:55618
> I0929 16:58:29.620779 3500 slave.cpp:729] Successfully authenticated with
> master [email protected]:55618
> I0929 16:58:29.621150 3500 slave.cpp:992] Will retry registration in
> 15.66596ms if necessary
> I0929 16:58:29.621526 3501 master.cpp:2930] Registering slave at
> slave(58)@192.168.122.164:55618 (fedora-20) with id
> 20140929-165829-2759502016-55618-3486-1
> I0929 16:58:29.621976 3501 registrar.cpp:421] Attempting to update the
> 'registry'
> I0929 16:58:29.623364 3506 log.cpp:680] Attempting to append 299 bytes to
> the log
> I0929 16:58:29.623780 3506 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 7
> I0929 16:58:29.624407 3506 replica.cpp:508] Replica received write request
> for position 7
> I0929 16:58:29.624712 3506 leveldb.cpp:343] Persisting action (318 bytes) to
> leveldb took 64462ns
> I0929 16:58:29.624984 3506 replica.cpp:676] Persisted action at 7
> I0929 16:58:29.625460 3506 replica.cpp:655] Replica received learned notice
> for position 7
> I0929 16:58:29.625838 3506 leveldb.cpp:343] Persisting action (320 bytes) to
> leveldb took 30316ns
> I0929 16:58:29.626093 3506 replica.cpp:676] Persisted action at 7
> I0929 16:58:29.626382 3506 replica.cpp:661] Replica learned APPEND action at
> position 7
> I0929 16:58:29.626832 3506 log.cpp:699] Attempting to truncate the log to 7
> I0929 16:58:29.627231 3506 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 8
> I0929 16:58:29.627789 3506 replica.cpp:508] Replica received write request
> for position 8
> I0929 16:58:29.628073 3506 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 26181ns
> I0929 16:58:29.628347 3506 replica.cpp:676] Persisted action at 8
> I0929 16:58:29.628829 3506 replica.cpp:655] Replica received learned notice
> for position 8
> I0929 16:58:29.629323 3506 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 28559ns
> I0929 16:58:29.629581 3506 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 22253ns
> I0929 16:58:29.629897 3506 replica.cpp:676] Persisted action at 8
> I0929 16:58:29.630159 3506 replica.cpp:661] Replica learned TRUNCATE action
> at position 8
> I0929 16:58:29.630910 3501 registrar.cpp:478] Successfully updated 'registry'
> I0929 16:58:29.631356 3501 master.cpp:2970] Registered slave
> 20140929-165829-2759502016-55618-3486-1 at slave(58)@192.168.122.164:55618
> (fedora-20)
> I0929 16:58:29.631624 3501 master.cpp:4180] Adding slave
> 20140929-165829-2759502016-55618-3486-1 at slave(58)@192.168.122.164:55618
> (fedora-20) with cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000]
> I0929 16:58:29.632066 3501 slave.cpp:763] Registered with master
> [email protected]:55618; given slave ID
> 20140929-165829-2759502016-55618-3486-1
> I0929 16:58:29.632493 3501 slave.cpp:2345] Received ping from
> slave-observer(57)@192.168.122.164:55618
> I0929 16:58:29.632298 3506 hierarchical_allocator_process.hpp:442] Added
> slave 20140929-165829-2759502016-55618-3486-1 (fedora-20) with cpus(*):3;
> mem(*):256; disk(*):1024; ports(*):[31000-32000] (and cpus(*):3; mem(*):256;
> disk(*):1024; ports(*):[31000-32000] available)
> I0929 16:58:29.633102 3506 hierarchical_allocator_process.hpp:734] Offering
> cpus(*):3; mem(*):256; disk(*):1024; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-1 to framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.633496 3507 master.hpp:868] Adding offer
> 20140929-165829-2759502016-55618-3486-1 with resources cpus(*):3; mem(*):256;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-1 (fedora-20)
> I0929 16:58:29.633833 3507 master.cpp:3679] Sending 1 offers to framework
> 20140929-165829-2759502016-55618-3486-0000
> I0929 16:58:29.634218 3507 sched.cpp:544] Scheduler::resourceOffers took
> 32550ns
> I0929 16:58:29.634784 3507 sched.cpp:745] Stopping framework
> '20140929-165829-2759502016-55618-3486-0000'
> I0929 16:58:29.634558 3486 master.cpp:676] Master terminating
> I0929 16:58:29.635319 3486 master.hpp:877] Removing offer
> 20140929-165829-2759502016-55618-3486-1 with resources cpus(*):3; mem(*):256;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140929-165829-2759502016-55618-3486-1 (fedora-20)
> I0929 16:58:29.635725 3506 hierarchical_allocator_process.hpp:679] Performed
> allocation for slave 20140929-165829-2759502016-55618-3486-1 in 2.656855ms
> I0929 16:58:29.644737 3503 slave.cpp:2430] [email protected]:55618
> exited
> W0929 16:58:29.645407 3503 slave.cpp:2433] Master disconnected! Waiting for
> a new master to be elected
> I0929 16:58:29.656318 3486 slave.cpp:477] Slave terminating
> tests/allocator_tests.cpp:1532: Failure
> Actual function call count doesn't match EXPECT_CALL(this->allocator,
> resourcesRecovered(_, _, _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] AllocatorTest/0.SlaveLost, where TypeParam =
> mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter,
> mesos::internal::master::allocator::DRFSorter> (179 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
