Vinod Kone created MESOS-743:
--------------------------------
Summary: ReservationAllocatorTest.ResourcesReturned test is flaky
Key: MESOS-743
URL: https://issues.apache.org/jira/browse/MESOS-743
Project: Mesos
Issue Type: Bug
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)
