[ https://issues.apache.org/jira/browse/MESOS-1782?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone updated MESOS-1782: ------------------------------ Shepherd: Benjamin Mahler Story Points: 1 (was: 2) > AllocatorTest/0.FrameworkExited is flaky > ---------------------------------------- > > Key: MESOS-1782 > URL: https://issues.apache.org/jira/browse/MESOS-1782 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 0.20.0 > Environment: ubuntu-12.04-gcc Jenkins VM > Reporter: Yan Xu > Assignee: Vinod Kone > > {noformat:title=} > [ RUN ] AllocatorTest/0.FrameworkExited > Using temporary directory '/tmp/AllocatorTest_0_FrameworkExited_B6WZng' > I0909 08:02:35.116555 18112 leveldb.cpp:176] Opened db in 31.64686ms > I0909 08:02:35.126065 18112 leveldb.cpp:183] Compacted db in 9.449823ms > I0909 08:02:35.126118 18112 leveldb.cpp:198] Created db iterator in 5858ns > I0909 08:02:35.126137 18112 leveldb.cpp:204] Seeked to beginning of db in > 1136ns > I0909 08:02:35.126150 18112 leveldb.cpp:273] Iterated through 0 keys in the > db in 560ns > I0909 08:02:35.126178 18112 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0909 08:02:35.126502 18133 recover.cpp:425] Starting replica recovery > I0909 08:02:35.126601 18133 recover.cpp:451] Replica is in EMPTY status > I0909 08:02:35.127012 18133 replica.cpp:638] Replica in EMPTY status received > a broadcasted recover request > I0909 08:02:35.127094 18133 recover.cpp:188] Received a recover response from > a replica in EMPTY status > I0909 08:02:35.127223 18133 recover.cpp:542] Updating replica status to > STARTING > I0909 08:02:35.226631 18133 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 99.308134ms > I0909 08:02:35.226690 18133 replica.cpp:320] Persisted replica status to > STARTING > I0909 08:02:35.226812 18131 recover.cpp:451] Replica is in STARTING status > I0909 08:02:35.227246 18131 replica.cpp:638] Replica in STARTING status > received a broadcasted recover request > I0909 08:02:35.227308 18131 recover.cpp:188] Received a recover response from > a replica in STARTING status > I0909 08:02:35.227409 18131 recover.cpp:542] Updating replica status to VOTING > I0909 08:02:35.228540 18129 master.cpp:286] Master > 20140909-080235-16842879-44005-18112 (precise) started on 127.0.1.1:44005 > I0909 08:02:35.228593 18129 master.cpp:332] Master only allowing > authenticated frameworks to register > I0909 08:02:35.228607 18129 master.cpp:337] Master only allowing > authenticated slaves to register > I0909 08:02:35.228620 18129 credentials.hpp:36] Loading credentials for > authentication from '/tmp/AllocatorTest_0_FrameworkExited_B6WZng/credentials' > I0909 08:02:35.228754 18129 master.cpp:366] Authorization enabled > I0909 08:02:35.229560 18129 master.cpp:120] No whitelist given. Advertising > offers for all slaves > I0909 08:02:35.229933 18129 hierarchical_allocator_process.hpp:299] > Initializing hierarchical allocator process with master : > master@127.0.1.1:44005 > I0909 08:02:35.230057 18127 master.cpp:1212] The newly elected leader is > master@127.0.1.1:44005 with id 20140909-080235-16842879-44005-18112 > I0909 08:02:35.230129 18127 master.cpp:1225] Elected as the leading master! > I0909 08:02:35.230144 18127 master.cpp:1043] Recovering from registrar > I0909 08:02:35.230257 18127 registrar.cpp:313] Recovering registrar > I0909 08:02:35.232461 18131 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 4.999384ms > I0909 08:02:35.232489 18131 replica.cpp:320] Persisted replica status to > VOTING > I0909 08:02:35.232544 18131 recover.cpp:556] Successfully joined the Paxos > group > I0909 08:02:35.232611 18131 recover.cpp:440] Recover process terminated > I0909 08:02:35.232727 18131 log.cpp:656] Attempting to start the writer > I0909 08:02:35.233012 18131 replica.cpp:474] Replica received implicit > promise request with proposal 1 > I0909 08:02:35.238785 18131 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 5.749504ms > I0909 08:02:35.238818 18131 replica.cpp:342] Persisted promised to 1 > I0909 08:02:35.244056 18131 coordinator.cpp:230] Coordinator attemping to > fill missing position > I0909 08:02:35.244580 18131 replica.cpp:375] Replica received explicit > promise request for position 0 with proposal 2 > I0909 08:02:35.250143 18131 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 5.382351ms > I0909 08:02:35.250319 18131 replica.cpp:676] Persisted action at 0 > I0909 08:02:35.250901 18131 replica.cpp:508] Replica received write request > for position 0 > I0909 08:02:35.251137 18131 leveldb.cpp:438] Reading position from leveldb > took 18689ns > I0909 08:02:35.256597 18131 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 5.274169ms > I0909 08:02:35.256764 18131 replica.cpp:676] Persisted action at 0 > I0909 08:02:35.263712 18126 replica.cpp:655] Replica received learned notice > for position 0 > I0909 08:02:35.269613 18126 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 5.417225ms > I0909 08:02:35.351641 18126 replica.cpp:676] Persisted action at 0 > I0909 08:02:35.351655 18126 replica.cpp:661] Replica learned NOP action at > position 0 > I0909 08:02:35.351889 18126 log.cpp:672] Writer started with ending position 0 > I0909 08:02:35.352165 18126 leveldb.cpp:438] Reading position from leveldb > took 25215ns > I0909 08:02:35.353163 18126 registrar.cpp:346] Successfully fetched the > registry (0B) > I0909 08:02:35.353185 18126 registrar.cpp:422] Attempting to update the > 'registry' > I0909 08:02:35.354152 18126 log.cpp:680] Attempting to append 120 bytes to > the log > I0909 08:02:35.354195 18126 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I0909 08:02:35.354416 18126 replica.cpp:508] Replica received write request > for position 1 > I0909 08:02:35.351579 18127 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I0909 08:02:35.354558 18127 hierarchical_allocator_process.hpp:659] Performed > allocation for 0 slaves in 2.984795ms > I0909 08:02:35.360254 18126 leveldb.cpp:343] Persisting action (137 bytes) to > leveldb took 5.811986ms > I0909 08:02:35.360285 18126 replica.cpp:676] Persisted action at 1 > I0909 08:02:35.364126 18132 replica.cpp:655] Replica received learned notice > for position 1 > I0909 08:02:35.369856 18132 leveldb.cpp:343] Persisting action (139 bytes) to > leveldb took 5.702756ms > I0909 08:02:35.369899 18132 replica.cpp:676] Persisted action at 1 > I0909 08:02:35.369910 18132 replica.cpp:661] Replica learned APPEND action at > position 1 > I0909 08:02:35.370209 18132 registrar.cpp:479] Successfully updated 'registry' > I0909 08:02:35.370311 18132 registrar.cpp:372] Successfully recovered > registrar > I0909 08:02:35.370477 18132 log.cpp:699] Attempting to truncate the log to 1 > I0909 08:02:35.370553 18132 master.cpp:1070] Recovered 0 slaves from the > Registry (84B) ; allowing 10mins for slaves to re-register > I0909 08:02:35.370594 18132 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I0909 08:02:35.371201 18127 replica.cpp:508] Replica received write request > for position 2 > I0909 08:02:35.376760 18127 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 5.264501ms > I0909 08:02:35.377105 18127 replica.cpp:676] Persisted action at 2 > I0909 08:02:35.377770 18127 replica.cpp:655] Replica received learned notice > for position 2 > I0909 08:02:35.383363 18127 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 5.272769ms > I0909 08:02:35.383818 18127 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 28148ns > I0909 08:02:35.384137 18127 replica.cpp:676] Persisted action at 2 > I0909 08:02:35.384399 18127 replica.cpp:661] Replica learned TRUNCATE action > at position 2 > I0909 08:02:35.396512 18127 slave.cpp:167] Slave started on > 64)@127.0.1.1:44005 > I0909 08:02:35.654770 18131 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I0909 08:02:35.654847 18131 hierarchical_allocator_process.hpp:659] Performed > allocation for 0 slaves in 104933ns > I0909 08:02:35.654974 18127 credentials.hpp:84] Loading credential for > authentication from '/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/credential' > I0909 08:02:35.655097 18127 slave.cpp:274] Slave using credential for: > test-principal > I0909 08:02:35.655203 18127 slave.cpp:287] Slave resources: cpus(*):3; > mem(*):1024; disk(*):25116; ports(*):[31000-32000] > I0909 08:02:35.655274 18127 slave.cpp:315] Slave hostname: precise > I0909 08:02:35.655285 18127 slave.cpp:316] Slave checkpoint: false > I0909 08:02:35.655804 18127 state.cpp:33] Recovering state from > '/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/meta' > I0909 08:02:35.655913 18127 status_update_manager.cpp:193] Recovering status > update manager > I0909 08:02:35.656005 18127 slave.cpp:3202] Finished recovery > I0909 08:02:35.656251 18127 slave.cpp:598] New master detected at > master@127.0.1.1:44005 > I0909 08:02:35.656285 18127 slave.cpp:672] Authenticating with master > master@127.0.1.1:44005 > I0909 08:02:35.656325 18127 slave.cpp:645] Detecting new master > I0909 08:02:35.656358 18127 status_update_manager.cpp:167] New master > detected at master@127.0.1.1:44005 > I0909 08:02:35.656389 18127 authenticatee.hpp:128] Creating new client SASL > connection > I0909 08:02:35.656563 18127 master.cpp:3653] Authenticating > slave(64)@127.0.1.1:44005 > I0909 08:02:35.656651 18127 authenticator.hpp:156] Creating new server SASL > connection > I0909 08:02:35.656770 18127 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0909 08:02:35.656796 18127 authenticatee.hpp:245] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0909 08:02:35.656822 18127 authenticator.hpp:262] Received SASL > authentication start > I0909 08:02:35.656858 18127 authenticator.hpp:384] Authentication requires > more steps > I0909 08:02:35.656883 18127 authenticatee.hpp:265] Received SASL > authentication step > I0909 08:02:35.656924 18127 authenticator.hpp:290] Received SASL > authentication step > I0909 08:02:35.656960 18127 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0909 08:02:35.656971 18127 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0909 08:02:35.656982 18127 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0909 08:02:35.656997 18127 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0909 08:02:35.657004 18127 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.657008 18127 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.657019 18127 authenticator.hpp:376] Authentication success > I0909 08:02:35.657047 18127 authenticatee.hpp:305] Authentication success > I0909 08:02:35.657073 18127 master.cpp:3693] Successfully authenticated > principal 'test-principal' at slave(64)@127.0.1.1:44005 > I0909 08:02:35.657145 18127 slave.cpp:729] Successfully authenticated with > master master@127.0.1.1:44005 > I0909 08:02:35.657183 18127 slave.cpp:980] Will retry registration in > 19.238717ms if necessary > I0909 08:02:35.657276 18128 master.cpp:2843] Registering slave at > slave(64)@127.0.1.1:44005 (precise) with id > 20140909-080235-16842879-44005-18112-0 > I0909 08:02:35.657389 18128 registrar.cpp:422] Attempting to update the > 'registry' > I0909 08:02:35.658382 18130 log.cpp:680] Attempting to append 295 bytes to > the log > I0909 08:02:35.658432 18130 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I0909 08:02:35.658635 18130 replica.cpp:508] Replica received write request > for position 3 > I0909 08:02:35.660959 18112 sched.cpp:137] Version: 0.21.0 > I0909 08:02:35.661093 18126 sched.cpp:233] New master detected at > master@127.0.1.1:44005 > I0909 08:02:35.661111 18126 sched.cpp:283] Authenticating with master > master@127.0.1.1:44005 > I0909 08:02:35.661175 18126 authenticatee.hpp:128] Creating new client SASL > connection > I0909 08:02:35.661306 18126 master.cpp:3653] Authenticating > scheduler-fd929918-7057-4fef-923a-ed9d6fd355be@127.0.1.1:44005 > I0909 08:02:35.661376 18126 authenticator.hpp:156] Creating new server SASL > connection > I0909 08:02:35.661466 18126 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0909 08:02:35.661483 18126 authenticatee.hpp:245] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0909 08:02:35.661504 18126 authenticator.hpp:262] Received SASL > authentication start > I0909 08:02:35.661530 18126 authenticator.hpp:384] Authentication requires > more steps > I0909 08:02:35.661552 18126 authenticatee.hpp:265] Received SASL > authentication step > I0909 08:02:35.661579 18126 authenticator.hpp:290] Received SASL > authentication step > I0909 08:02:35.661592 18126 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0909 08:02:35.661598 18126 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0909 08:02:35.661607 18126 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0909 08:02:35.661613 18126 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0909 08:02:35.661619 18126 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.661623 18126 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.661633 18126 authenticator.hpp:376] Authentication success > I0909 08:02:35.661653 18126 authenticatee.hpp:305] Authentication success > I0909 08:02:35.661672 18126 master.cpp:3693] Successfully authenticated > principal 'test-principal' at > scheduler-fd929918-7057-4fef-923a-ed9d6fd355be@127.0.1.1:44005 > I0909 08:02:35.661730 18126 sched.cpp:357] Successfully authenticated with > master master@127.0.1.1:44005 > I0909 08:02:35.661741 18126 sched.cpp:476] Sending registration request to > master@127.0.1.1:44005 > I0909 08:02:35.661782 18126 master.cpp:1331] Received registration request > from scheduler-fd929918-7057-4fef-923a-ed9d6fd355be@127.0.1.1:44005 > I0909 08:02:35.661798 18126 master.cpp:1291] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0909 08:02:35.661917 18126 master.cpp:1390] Registering framework > 20140909-080235-16842879-44005-18112-0000 at > scheduler-fd929918-7057-4fef-923a-ed9d6fd355be@127.0.1.1:44005 > I0909 08:02:35.662017 18126 sched.cpp:407] Framework registered with > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.662039 18126 sched.cpp:421] Scheduler::registered took 9070ns > I0909 08:02:35.662119 18126 hierarchical_allocator_process.hpp:329] Added > framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.662130 18126 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I0909 08:02:35.662135 18126 hierarchical_allocator_process.hpp:659] Performed > allocation for 0 slaves in 5558ns > I0909 08:02:35.672230 18130 leveldb.cpp:343] Persisting action (314 bytes) to > leveldb took 13.567526ms > I0909 08:02:35.672268 18130 replica.cpp:676] Persisted action at 3 > I0909 08:02:35.672483 18130 replica.cpp:655] Replica received learned notice > for position 3 > I0909 08:02:35.677322 18132 slave.cpp:980] Will retry registration in > 14.890338ms if necessary > I0909 08:02:35.677399 18132 master.cpp:2831] Ignoring register slave message > from slave(64)@127.0.1.1:44005 (precise) as admission is already in progress > I0909 08:02:35.680881 18130 leveldb.cpp:343] Persisting action (316 bytes) to > leveldb took 8.376798ms > I0909 08:02:35.680908 18130 replica.cpp:676] Persisted action at 3 > I0909 08:02:35.680917 18130 replica.cpp:661] Replica learned APPEND action at > position 3 > I0909 08:02:35.681252 18130 registrar.cpp:479] Successfully updated 'registry' > I0909 08:02:35.681330 18130 log.cpp:699] Attempting to truncate the log to 3 > I0909 08:02:35.681385 18130 master.cpp:2883] Registered slave > 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise) > I0909 08:02:35.681399 18130 master.cpp:4126] Adding slave > 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise) > with cpus(*):3; mem(*):1024; disk(*):25116; ports(*):[31000-32000] > I0909 08:02:35.681504 18130 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I0909 08:02:35.681570 18130 slave.cpp:763] Registered with master > master@127.0.1.1:44005; given slave ID 20140909-080235-16842879-44005-18112-0 > I0909 08:02:35.681689 18130 slave.cpp:2329] Received ping from > slave-observer(50)@127.0.1.1:44005 > I0909 08:02:35.681753 18130 hierarchical_allocator_process.hpp:442] Added > slave 20140909-080235-16842879-44005-18112-0 (precise) with cpus(*):3; > mem(*):1024; disk(*):25116; ports(*):[31000-32000] (and cpus(*):3; > mem(*):1024; disk(*):25116; ports(*):[31000-32000] available) > I0909 08:02:35.681808 18130 hierarchical_allocator_process.hpp:734] Offering > cpus(*):3; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 to framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.681892 18130 hierarchical_allocator_process.hpp:679] Performed > allocation for slave 20140909-080235-16842879-44005-18112-0 in 109580ns > I0909 08:02:35.681968 18130 master.hpp:861] Adding offer > 20140909-080235-16842879-44005-18112-0 with resources cpus(*):3; mem(*):1024; > disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.682014 18130 master.cpp:3600] Sending 1 offers to framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.682443 18130 sched.cpp:544] Scheduler::resourceOffers took > 254258ns > I0909 08:02:35.682633 18130 master.hpp:871] Removing offer > 20140909-080235-16842879-44005-18112-0 with resources cpus(*):3; mem(*):1024; > disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.682684 18130 master.cpp:2201] Processing reply for offers: [ > 20140909-080235-16842879-44005-18112-0 ] on slave > 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise) > for framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.682708 18130 master.cpp:2284] Authorizing framework principal > 'test-principal' to launch task 0 as user 'jenkins' > I0909 08:02:35.682971 18130 replica.cpp:508] Replica received write request > for position 4 > I0909 08:02:35.683132 18132 master.hpp:833] Adding task 0 with resources > cpus(*):2; mem(*):512 on slave 20140909-080235-16842879-44005-18112-0 > (precise) > I0909 08:02:35.683159 18132 master.cpp:2350] Launching task 0 of framework > 20140909-080235-16842879-44005-18112-0000 with resources cpus(*):2; > mem(*):512 on slave 20140909-080235-16842879-44005-18112-0 at > slave(64)@127.0.1.1:44005 (precise) > I0909 08:02:35.683363 18132 slave.cpp:1011] Got assigned task 0 for framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.683580 18132 slave.cpp:1121] Launching task 0 for framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.684833 18133 hierarchical_allocator_process.hpp:563] Recovered > cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000] (total > allocatable: cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000]) on > slave 20140909-080235-16842879-44005-18112-0 from framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.684864 18133 hierarchical_allocator_process.hpp:599] Framework > 20140909-080235-16842879-44005-18112-0000 filtered slave > 20140909-080235-16842879-44005-18112-0 for 5secs > I0909 08:02:35.686401 18132 exec.cpp:132] Version: 0.21.0 > I0909 08:02:35.686848 18128 exec.cpp:182] Executor started at: > executor(8)@127.0.1.1:44005 with pid 18112 > I0909 08:02:35.687095 18132 slave.cpp:1231] Queuing task '0' for executor > executor-1 of framework '20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.687302 18132 slave.cpp:552] Successfully attached file > '/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/slaves/20140909-080235-16842879-44005-18112-0/frameworks/20140909-080235-16842879-44005-18112-0000/executors/executor-1/runs/c4458e43-94ee-4b5e-bd74-5d39a09deff6' > I0909 08:02:35.687568 18132 slave.cpp:1741] Got registration for executor > 'executor-1' of framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.687893 18127 exec.cpp:206] Executor registered on slave > 20140909-080235-16842879-44005-18112-0 > I0909 08:02:35.688789 18127 exec.cpp:218] Executor::registered took 15015ns > I0909 08:02:35.688977 18132 slave.cpp:1859] Flushing queued task 0 for > executor 'executor-1' of framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.689260 18133 exec.cpp:293] Executor asked to run task '0' > I0909 08:02:35.689441 18133 exec.cpp:302] Executor::launchTask took 24599ns > I0909 08:02:35.691651 18112 sched.cpp:137] Version: 0.21.0 > I0909 08:02:35.691946 18131 sched.cpp:233] New master detected at > master@127.0.1.1:44005 > I0909 08:02:35.692126 18131 sched.cpp:283] Authenticating with master > master@127.0.1.1:44005 > I0909 08:02:35.692399 18131 authenticatee.hpp:128] Creating new client SASL > connection > I0909 08:02:35.692791 18131 master.cpp:3653] Authenticating > scheduler-6e711fc6-aad6-48bd-9ce7-2316b45c5482@127.0.1.1:44005 > I0909 08:02:35.693068 18131 authenticator.hpp:156] Creating new server SASL > connection > I0909 08:02:35.693351 18131 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0909 08:02:35.693532 18131 authenticatee.hpp:245] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0909 08:02:35.693739 18131 authenticator.hpp:262] Received SASL > authentication start > I0909 08:02:35.693979 18131 authenticator.hpp:384] Authentication requires > more steps > I0909 08:02:35.694202 18131 authenticatee.hpp:265] Received SASL > authentication step > I0909 08:02:35.694449 18131 authenticator.hpp:290] Received SASL > authentication step > I0909 08:02:35.694633 18131 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0909 08:02:35.694792 18131 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0909 08:02:35.694980 18131 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0909 08:02:35.695158 18131 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'precise' server FQDN: 'precise' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0909 08:02:35.695369 18131 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.695724 18131 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0909 08:02:35.695907 18131 authenticator.hpp:376] Authentication success > I0909 08:02:35.696117 18128 authenticatee.hpp:305] Authentication success > I0909 08:02:35.698509 18130 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 15.520863ms > I0909 08:02:35.698698 18130 replica.cpp:676] Persisted action at 4 > I0909 08:02:35.698940 18128 sched.cpp:357] Successfully authenticated with > master master@127.0.1.1:44005 > I0909 08:02:35.699095 18126 master.cpp:3693] Successfully authenticated > principal 'test-principal' at > scheduler-6e711fc6-aad6-48bd-9ce7-2316b45c5482@127.0.1.1:44005 > I0909 08:02:35.699354 18130 replica.cpp:655] Replica received learned notice > for position 4 > I0909 08:02:35.699973 18128 sched.cpp:476] Sending registration request to > master@127.0.1.1:44005 > I0909 08:02:35.700265 18128 master.cpp:1331] Received registration request > from scheduler-6e711fc6-aad6-48bd-9ce7-2316b45c5482@127.0.1.1:44005 > I0909 08:02:35.700515 18128 master.cpp:1291] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0909 08:02:35.700809 18128 master.cpp:1390] Registering framework > 20140909-080235-16842879-44005-18112-0001 at > scheduler-6e711fc6-aad6-48bd-9ce7-2316b45c5482@127.0.1.1:44005 > I0909 08:02:35.701037 18133 sched.cpp:407] Framework registered with > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.701211 18133 sched.cpp:421] Scheduler::registered took 11991ns > I0909 08:02:35.701488 18131 hierarchical_allocator_process.hpp:329] Added > framework 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.701728 18131 hierarchical_allocator_process.hpp:734] Offering > cpus(*):1; mem(*):512; disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 to framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.701992 18131 hierarchical_allocator_process.hpp:659] Performed > allocation for 1 slaves in 297969ns > I0909 08:02:35.702229 18128 master.hpp:861] Adding offer > 20140909-080235-16842879-44005-18112-1 with resources cpus(*):1; mem(*):512; > disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.702481 18128 master.cpp:3600] Sending 1 offers to framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.702901 18129 sched.cpp:544] Scheduler::resourceOffers took > 127949ns > I0909 08:02:35.703305 18128 master.hpp:871] Removing offer > 20140909-080235-16842879-44005-18112-1 with resources cpus(*):1; mem(*):512; > disk(*):25116; ports(*):[31000-32000] on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.703629 18128 master.cpp:2201] Processing reply for offers: [ > 20140909-080235-16842879-44005-18112-1 ] on slave > 20140909-080235-16842879-44005-18112-0 at slave(64)@127.0.1.1:44005 (precise) > for framework 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.703908 18128 master.cpp:2284] Authorizing framework principal > 'test-principal' to launch task 0 as user 'jenkins' > I0909 08:02:35.703789 18132 slave.cpp:2542] Monitoring executor 'executor-1' > of framework '20140909-080235-16842879-44005-18112-0000' in container > 'c4458e43-94ee-4b5e-bd74-5d39a09deff6' > I0909 08:02:35.704763 18128 master.hpp:833] Adding task 0 with resources > cpus(*):1; mem(*):256 on slave 20140909-080235-16842879-44005-18112-0 > (precise) > I0909 08:02:35.704951 18128 master.cpp:2350] Launching task 0 of framework > 20140909-080235-16842879-44005-18112-0001 with resources cpus(*):1; > mem(*):256 on slave 20140909-080235-16842879-44005-18112-0 at > slave(64)@127.0.1.1:44005 (precise) > I0909 08:02:35.705255 18129 slave.cpp:1011] Got assigned task 0 for framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.705582 18129 slave.cpp:1121] Launching task 0 for framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.707756 18129 exec.cpp:132] Version: 0.21.0 > I0909 08:02:35.708035 18130 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 8.127072ms > I0909 08:02:35.708281 18130 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 28817ns > I0909 08:02:35.708459 18130 replica.cpp:676] Persisted action at 4 > I0909 08:02:35.708632 18130 replica.cpp:661] Replica learned TRUNCATE action > at position 4 > I0909 08:02:35.708869 18133 exec.cpp:182] Executor started at: > executor(9)@127.0.1.1:44005 with pid 18112 > I0909 08:02:35.709120 18127 hierarchical_allocator_process.hpp:659] Performed > allocation for 1 slaves in 35083ns > I0909 08:02:35.709511 18129 slave.cpp:1231] Queuing task '0' for executor > executor-2 of framework '20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.709707 18129 slave.cpp:552] Successfully attached file > '/tmp/AllocatorTest_0_FrameworkExited_xV9Mk4/slaves/20140909-080235-16842879-44005-18112-0/frameworks/20140909-080235-16842879-44005-18112-0001/executors/executor-2/runs/7654870b-fd36-40b2-aac7-37b1bcfa821e' > I0909 08:02:35.709913 18129 slave.cpp:1741] Got registration for executor > 'executor-2' of framework 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.710188 18129 slave.cpp:1859] Flushing queued task 0 for > executor 'executor-2' of framework 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.710516 18129 slave.cpp:2542] Monitoring executor 'executor-2' > of framework '20140909-080235-16842879-44005-18112-0001' in container > '7654870b-fd36-40b2-aac7-37b1bcfa821e' > I0909 08:02:35.710321 18130 exec.cpp:206] Executor registered on slave > 20140909-080235-16842879-44005-18112-0 > I0909 08:02:35.711678 18130 exec.cpp:218] Executor::registered took 14355ns > I0909 08:02:35.711987 18130 exec.cpp:293] Executor asked to run task '0' > I0909 08:02:35.715551 18130 exec.cpp:302] Executor::launchTask took 3.40476ms > I0909 08:02:35.716006 18131 sched.cpp:745] Stopping framework > '20140909-080235-16842879-44005-18112-0000' > I0909 08:02:35.716292 18128 master.cpp:1640] Asked to unregister framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.716490 18127 hierarchical_allocator_process.hpp:563] Recovered > mem(*):256; disk(*):25116; ports(*):[31000-32000] (total allocatable: > mem(*):256; disk(*):25116; ports(*):[31000-32000]) on slave > 20140909-080235-16842879-44005-18112-0 from framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.716792 18127 hierarchical_allocator_process.hpp:599] Framework > 20140909-080235-16842879-44005-18112-0001 filtered slave > 20140909-080235-16842879-44005-18112-0 for 5secs > I0909 08:02:35.717018 18128 master.cpp:3976] Removing framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.717269 18128 master.hpp:851] Removing task 0 with resources > cpus(*):2; mem(*):512 on slave 20140909-080235-16842879-44005-18112-0 > (precise) > W0909 08:02:35.717607 18128 master.cpp:4419] Removing task 0 of framework > 20140909-080235-16842879-44005-18112-0000 and slave > 20140909-080235-16842879-44005-18112-0 in non-terminal state TASK_STAGING > I0909 08:02:35.717470 18131 hierarchical_allocator_process.hpp:405] > Deactivated framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.718065 18131 hierarchical_allocator_process.hpp:563] Recovered > cpus(*):2; mem(*):512 (total allocatable: mem(*):768; disk(*):25116; > ports(*):[31000-32000]; cpus(*):2) on slave > 20140909-080235-16842879-44005-18112-0 from framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.717438 18132 slave.cpp:1414] Asked to shut down framework > 20140909-080235-16842879-44005-18112-0000 by master@127.0.1.1:44005 > I0909 08:02:35.718444 18132 slave.cpp:1439] Shutting down framework > 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.718621 18132 slave.cpp:2882] Shutting down executor > 'executor-1' of framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.718843 18133 exec.cpp:379] Executor asked to shutdown > I0909 08:02:35.719022 18133 exec.cpp:394] Executor::shutdown took 13745ns > I0909 08:02:35.722009 18128 hierarchical_allocator_process.hpp:360] Removed > framework 20140909-080235-16842879-44005-18112-0000 > I0909 08:02:35.830785 18131 hierarchical_allocator_process.hpp:734] Offering > mem(*):768; disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave > 20140909-080235-16842879-44005-18112-0 to framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.830940 18131 hierarchical_allocator_process.hpp:659] Performed > allocation for 1 slaves in 218030ns > I0909 08:02:35.831056 18127 master.hpp:861] Adding offer > 20140909-080235-16842879-44005-18112-2 with resources mem(*):768; > disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.831115 18127 master.cpp:3600] Sending 1 offers to framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.831248 18127 sched.cpp:544] Scheduler::resourceOffers took > 18178ns > I0909 08:02:35.831387 18112 master.cpp:650] Master terminating > I0909 08:02:35.831441 18112 master.hpp:851] Removing task 0 with resources > cpus(*):1; mem(*):256 on slave 20140909-080235-16842879-44005-18112-0 > (precise) > W0909 08:02:35.831488 18112 master.cpp:4419] Removing task 0 of framework > 20140909-080235-16842879-44005-18112-0001 and slave > 20140909-080235-16842879-44005-18112-0 in non-terminal state TASK_STAGING > I0909 08:02:35.831573 18112 master.hpp:871] Removing offer > 20140909-080235-16842879-44005-18112-2 with resources mem(*):768; > disk(*):25116; ports(*):[31000-32000]; cpus(*):2 on slave > 20140909-080235-16842879-44005-18112-0 (precise) > I0909 08:02:35.832608 18112 slave.cpp:475] Slave terminating > I0909 08:02:35.832630 18112 slave.cpp:1414] Asked to shut down framework > 20140909-080235-16842879-44005-18112-0000 by @0.0.0.0:0 > W0909 08:02:35.832643 18112 slave.cpp:1435] Ignoring shutdown framework > 20140909-080235-16842879-44005-18112-0000 because it is terminating > I0909 08:02:35.832648 18112 slave.cpp:1414] Asked to shut down framework > 20140909-080235-16842879-44005-18112-0001 by @0.0.0.0:0 > I0909 08:02:35.832654 18112 slave.cpp:1439] Shutting down framework > 20140909-080235-16842879-44005-18112-0001 > I0909 08:02:35.832664 18112 slave.cpp:2882] Shutting down executor > 'executor-2' of framework 20140909-080235-16842879-44005-18112-0001 > tests/allocator_tests.cpp:1444: 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.FrameworkExited, where TypeParam = > mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, > mesos::internal::master::allocator::DRFSorter> (756 ms) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)