[
https://issues.apache.org/jira/browse/MESOS-743?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vinod Kone updated MESOS-743:
-----------------------------
Component/s: test
> ReservationAllocatorTest.ResourcesReturned test is flaky
> --------------------------------------------------------
>
> Key: MESOS-743
> URL: https://issues.apache.org/jira/browse/MESOS-743
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Fix For: 0.15.0
>
>
> [ RUN ] ReservationAllocatorTest.ResourcesReturned
> I1015 21:53:05.024520 5174 master.cpp:284] Master started on
> 67.195.138.9:55602
> I1015 21:53:05.135216 5174 master.cpp:299] Master ID:
> 201310152153-160088899-55602-5154
> I1015 21:53:05.358496 5174 master.cpp:302] Master only allowing
> authenticated frameworks to register!
> I1015 21:53:05.358873 5176 master.cpp:85] No whitelist given. Advertising
> offers for all slaves
> I1015 21:53:05.025017 5175 slave.cpp:108] Slave started on
> 11)@67.195.138.9:55602
> I1015 21:53:05.025459 5178 slave.cpp:108] Slave started on
> 12)@67.195.138.9:55602
> I1015 21:53:05.736470 5178 slave.cpp:208] Slave resources: cpus(role3):4;
> mem(*):1024; disk(*):0; ports(*):[31000-32000]
> I1015 21:53:05.025756 5173 sched.cpp:195] New master at
> [email protected]:55602
> I1015 21:53:05.964328 5173 sched.cpp:281] Authenticating with master
> [email protected]:55602
> I1015 21:53:06.080032 5173 authenticatee.hpp:124] Creating new client SASL
> connection
> I1015 21:53:05.358954 5174 master.cpp:697] Elected as master!
> I1015 21:53:06.313797 5174 master.cpp:1723] Authenticating framework at
> scheduler(8)@67.195.138.9:55602
> I1015 21:53:05.358958 5180 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]:55602
> I1015 21:53:05.625615 5175 slave.cpp:208] Slave resources: cpus(role1):1;
> mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000]
> I1015 21:53:05.857185 5178 slave.cpp:547] New master detected at
> [email protected]:55602
> I1015 21:53:06.430922 5177 authenticator.hpp:140] Creating new server SASL
> connection
> I1015 21:53:06.903149 5177 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I1015 21:53:07.018589 5177 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1015 21:53:06.787698 5178 slave.cpp:562] Postponing registration until
> recovery is complete
> I1015 21:53:07.244017 5178 slave.cpp:399] Finished recovery
> I1015 21:53:06.598923 5176 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I1015 21:53:06.670398 5175 slave.cpp:547] New master detected at
> [email protected]:55602
> I1015 21:53:07.587999 5175 slave.cpp:562] Postponing registration until
> recovery is complete
> I1015 21:53:07.703451 5175 slave.cpp:399] Finished recovery
> I1015 21:53:07.361182 5179 master.cpp:1248] Attempting to register slave on
> vesta.apache.org at slave(12)@67.195.138.9:55602
> I1015 21:53:07.480469 5176 hierarchical_allocator_process.hpp:688] Performed
> allocation for 0 slaves in 881.553255ms
> I1015 21:53:07.132475 5177 authenticator.hpp:243] Received SASL
> authentication start
> I1015 21:53:07.588052 5174 status_update_manager.cpp:157] New master
> detected at [email protected]:55602
> I1015 21:53:06.787698 5173 status_update_manager.cpp:157] New master
> detected at [email protected]:55602
> I1015 21:53:07.930415 5179 master.cpp:2502] Adding slave
> 201310152153-160088899-55602-5154-0 at vesta.apache.org with cpus(role3):4;
> mem(*):1024; disk(*):0; ports(*):[31000-32000]
> I1015 21:53:08.088093 5175 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I1015 21:53:08.587415 5175 hierarchical_allocator_process.hpp:688] Performed
> allocation for 0 slaves in 499.327569ms
> I1015 21:53:08.468082 5180 slave.cpp:613] Registered with master
> [email protected]:55602; given slave ID 201310152153-160088899-55602-5154-0
> I1015 21:53:08.468166 5179 master.cpp:1248] Attempting to register slave on
> vesta.apache.org at slave(11)@67.195.138.9:55602
> I1015 21:53:08.145501 5177 authenticator.hpp:325] Authentication requires
> more steps
> I1015 21:53:09.053948 5177 authenticatee.hpp:258] Received SASL
> authentication step
> I1015 21:53:09.173583 5177 authenticator.hpp:271] Received SASL
> authentication step
> I1015 21:53:09.285169 5177 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'vesta.apache.org' server FQDN:
> 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1015 21:53:09.400761 5177 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1015 21:53:09.516391 5177 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1015 21:53:09.631989 5177 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'vesta.apache.org' server FQDN:
> 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1015 21:53:09.743607 5177 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1015 21:53:09.857619 5177 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1015 21:53:10.134296 5177 authenticator.hpp:317] Authentication success
> I1015 21:53:08.934339 5179 master.cpp:2502] Adding slave
> 201310152153-160088899-55602-5154-1 at vesta.apache.org with cpus(role1):1;
> mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000]
> I1015 21:53:08.707186 5175 hierarchical_allocator_process.hpp:445] Added
> slave 201310152153-160088899-55602-5154-0 (vesta.apache.org) with
> cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000] (and
> cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000] available)
> I1015 21:53:10.391702 5175 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 201310152153-160088899-55602-5154-0 in 13.68us
> I1015 21:53:10.636656 5175 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 10.474us
> I1015 21:53:10.371569 5179 master.cpp:1236] Slave
> 201310152153-160088899-55602-5154-0 (vesta.apache.org) already registered,
> resending acknowledgement
> I1015 21:53:10.863911 5179 master.cpp:1236] Slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org) already registered,
> resending acknowledgement
> I1015 21:53:10.972573 5179 master.cpp:1236] Slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org) already registered,
> resending acknowledgement
> I1015 21:53:11.083143 5179 master.cpp:1763] Successfully authenticated
> framework at scheduler(8)@67.195.138.9:55602
> I1015 21:53:10.752401 5175 hierarchical_allocator_process.hpp:445] Added
> slave 201310152153-160088899-55602-5154-1 (vesta.apache.org) with
> cpus(role1):1; mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1;
> mem(*):200; disk(*):0; ports(*):[31000-32000] (and cpus(role1):1;
> mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000] available)
> I1015 21:53:11.314399 5175 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 201310152153-160088899-55602-5154-1 in 29.664us
> W1015 21:53:10.863941 5178 slave.cpp:637] Already registered with master
> [email protected]:55602
> I1015 21:53:10.514277 5173 master.cpp:85] No whitelist given. Advertising
> offers for all slaves
> W1015 21:53:11.080916 5176 sched.cpp:347] Authentication timed out
> W1015 21:53:11.776898 5176 sched.cpp:307] Failed to authenticate with master
> [email protected]:55602: future discarded
> I1015 21:53:10.247900 5177 authenticatee.hpp:298] Authentication success
> I1015 21:53:11.422001 5175 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 11.813us
> I1015 21:53:10.371490 5180 slave.cpp:613] Registered with master
> [email protected]:55602; given slave ID 201310152153-160088899-55602-5154-1
> W1015 21:53:12.223341 5180 slave.cpp:637] Already registered with master
> [email protected]:55602
> W1015 21:53:12.334908 5180 slave.cpp:637] Already registered with master
> [email protected]:55602
> I1015 21:53:12.003942 5176 sched.cpp:281] Authenticating with master
> [email protected]:55602
> I1015 21:53:12.565399 5176 authenticatee.hpp:124] Creating new client SASL
> connection
> I1015 21:53:12.684839 5176 master.cpp:1723] Authenticating framework at
> scheduler(8)@67.195.138.9:55602
> I1015 21:53:12.805451 5176 authenticator.hpp:140] Creating new server SASL
> connection
> I1015 21:53:12.913019 5176 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I1015 21:53:12.165845 5177 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 21.98us
> I1015 21:53:13.031170 5176 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1015 21:53:13.266094 5176 authenticator.hpp:243] Received SASL
> authentication start
> I1015 21:53:13.379432 5176 authenticator.hpp:325] Authentication requires
> more steps
> I1015 21:53:13.198365 5174 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 25.967us
> I1015 21:53:13.497118 5179 authenticatee.hpp:258] Received SASL
> authentication step
> I1015 21:53:13.730234 5179 authenticator.hpp:271] Received SASL
> authentication step
> I1015 21:53:13.847440 5179 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'vesta.apache.org' server FQDN:
> 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1015 21:53:13.966887 5179 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1015 21:53:14.082396 5179 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1015 21:53:14.189903 5179 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'vesta.apache.org' server FQDN:
> 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1015 21:53:14.305390 5179 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1015 21:53:14.423897 5179 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1015 21:53:14.540318 5179 authenticator.hpp:317] Authentication success
> I1015 21:53:14.647845 5179 authenticatee.hpp:298] Authentication success
> I1015 21:53:14.759363 5179 sched.cpp:326] Successfully authenticated with
> master [email protected]:55602
> I1015 21:53:14.647902 5178 master.cpp:1763] Successfully authenticated
> framework at scheduler(8)@67.195.138.9:55602
> ../../src/tests/allocator_tests.cpp:550: Failure
> Failed to wait 10secs for launchTask
> I1015 21:53:13.664774 5176 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 19.445us
> I1015 21:53:14.990371 5178 master.cpp:768] Received registration request
> from scheduler(8)@67.195.138.9:55602
> I1015 21:53:15.221333 5178 master.cpp:786] Registering framework
> 201310152153-160088899-55602-5154-0000 at scheduler(8)@67.195.138.9:55602
> I1015 21:53:15.340879 5178 sched.cpp:365] Framework registered with
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:15.456460 5178 sched.cpp:379] Scheduler::registered took 31.589us
> I1015 21:53:15.155944 5179 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 24.662us
> I1015 21:53:15.584105 5179 hierarchical_allocator_process.hpp:332] Added
> framework 201310152153-160088899-55602-5154-0000
> I1015 21:53:15.743541 5179 hierarchical_allocator_process.hpp:752] Offering
> cpus(*):1; mem(*):200; disk(*):0; ports(*):[31000-32000]; cpus(role1):1;
> mem(role1):200 on slave 201310152153-160088899-55602-5154-1 to framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:15.855206 5179 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 111.76082ms
> I1015 21:53:15.965875 5179 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 58.9us
> I1015 21:53:15.855288 5173 master.hpp:389] Adding offer
> 201310152153-160088899-55602-5154-0 with resources cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000]; cpus(role1):1; mem(role1):200 on slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org)
> I1015 21:53:16.123545 5180 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 65.147us
> I1015 21:53:16.182025 5173 master.cpp:1689] Sending 1 offers to framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:16.339861 5177 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 76.223us
> I1015 21:53:16.397686 5174 sched.cpp:472] Scheduler::resourceOffers took
> 237.047us
> I1015 21:53:16.555155 5173 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 65.938us
> I1015 21:53:16.612658 5174 master.cpp:2015] Processing reply for offer
> 201310152153-160088899-55602-5154-0 on slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org) for framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:16.666290 5176 master.cpp:85] No whitelist given. Advertising
> offers for all slaves
> I1015 21:53:16.772609 5178 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 67us
> I1015 21:53:16.837975 5174 master.hpp:361] Adding task 0 with resources
> cpus(role1):1; mem(role1):100 on slave 201310152153-160088899-55602-5154-1
> (vesta.apache.org)
> I1015 21:53:17.160363 5174 master.cpp:2139] Launching task 0 of framework
> 201310152153-160088899-55602-5154-0000 with resources cpus(role1):1;
> mem(role1):100 on slave 201310152153-160088899-55602-5154-1 (vesta.apache.org)
> I1015 21:53:17.274443 5174 master.hpp:399] Removing offer
> 201310152153-160088899-55602-5154-0 with resources cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000]; cpus(role1):1; mem(role1):200 on slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org)
> I1015 21:53:17.103066 5175 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 60.435us
> I1015 21:53:17.274504 5179 slave.cpp:786] Got assigned task 0 for framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:17.502904 5175 hierarchical_allocator_process.hpp:547] Framework
> 201310152153-160088899-55602-5154-0000 left cpus(*):1; mem(*):200;
> ports(*):[31000-32000]; mem(role1):100 unused on slave
> 201310152153-160088899-55602-5154-1
> I1015 21:53:17.721963 5175 hierarchical_allocator_process.hpp:752] Offering
> cpus(*):1; mem(*):200; disk(*):0; ports(*):[31000-32000]; mem(role1):100 on
> slave 201310152153-160088899-55602-5154-1 to framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:17.614588 5179 slave.cpp:897] Launching task 0 for framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:17.852473 5175 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 130.555374ms
> I1015 21:53:17.852542 5173 master.hpp:389] Adding offer
> 201310152153-160088899-55602-5154-1 with resources cpus(*):1; mem(*):200;
> disk(*):0; ports(*):[31000-32000]; mem(role1):100 on slave
> 201310152153-160088899-55602-5154-1 (vesta.apache.org)
> I1015 21:53:18.016932 5179 slave.cpp:1008] Queuing task '0' for executor
> default of framework '201310152153-160088899-55602-5154-0000
> I1015 21:53:18.347012 5179 slave.cpp:529] Successfully attached file
> '/tmp/ReservationAllocatorTest_ResourcesReturned_uUqLYm/slaves/201310152153-160088899-55602-5154-1/frameworks/201310152153-160088899-55602-5154-0000/executors/default/runs/5029b350-e9b0-4608-95ab-a14da61413be'
> I1015 21:53:18.170222 5176 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 43.916us
> I1015 21:53:18.243527 5173 master.cpp:1689] Sending 1 offers to framework
> 201310152153-160088899-55602-5154-0000
> I1015 21:53:18.657771 5173 sched.cpp:472] Scheduler::resourceOffers took
> 21.881us
> I1015 21:53:18.604254 5178 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 48.042us
> I1015 21:53:18.017834 5177 exec.cpp:174] Executor started at:
> executor(1)@67.195.138.9:55602 with pid 5154
> I1015 21:53:18.976598 5177 slave.cpp:1460] Got registration for executor
> 'default' of framework 201310152153-160088899-55602-5154-0000
> I1015 21:53:18.923197 5180 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 52.261us
> I1015 21:53:19.084350 5177 slave.cpp:1581] Flushing queued task 0 for
> executor 'default' of framework 201310152153-160088899-55602-5154-0000
> I1015 21:53:19.084408 5175 exec.cpp:198] Executor registered on slave
> 201310152153-160088899-55602-5154-1
> I1015 21:53:19.238127 5174 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 55.4us
> I1015 21:53:19.403947 5175 exec.cpp:210] Executor::registered took 16.206us
> I1015 21:53:19.451490 5178 monitor.cpp:187] Publishing resource usage for
> executor 'default' of framework '201310152153-160088899-55602-5154-0000'
> I1015 21:53:19.557031 5179 hierarchical_allocator_process.hpp:688] Performed
> allocation for 2 slaves in 60.017us
> I1015 21:53:19.614536 5175 exec.cpp:285] Executor asked to run task '0'
> pure virtual method called
> terminate called without an active exception
--
This message was sent by Atlassian JIRA
(v6.1#6144)
