You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/09/29 20:10:35 UTC
[jira] [Updated] (MESOS-1782) AllocatorTest/0.FrameworkExited is
flaky
[ https://issues.apache.org/jira/browse/MESOS-1782?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone updated MESOS-1782:
------------------------------
Sprint: Mesos Q3 Sprint 6
Assignee: Vinod Kone
Story Points: 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)