You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Yan Xu (JIRA)" <ji...@apache.org> on 2014/04/22 21:34:19 UTC
[jira] [Assigned] (MESOS-743)
ReservationAllocatorTest.ResourcesReturned test is flaky
[ https://issues.apache.org/jira/browse/MESOS-743?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Yan Xu reassigned MESOS-743:
----------------------------
Assignee: Yan Xu
> 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
> Assignee: Yan Xu
> Fix For: 0.19.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 master@67.195.138.9:55602
> I1015 21:53:05.964328 5173 sched.cpp:281] Authenticating with master master@67.195.138.9: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 : master@67.195.138.9: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 master@67.195.138.9: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 master@67.195.138.9: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 master@67.195.138.9:55602
> I1015 21:53:06.787698 5173 status_update_manager.cpp:157] New master detected at master@67.195.138.9: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 master@67.195.138.9: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 master@67.195.138.9: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 master@67.195.138.9: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 master@67.195.138.9:55602; given slave ID 201310152153-160088899-55602-5154-1
> W1015 21:53:12.223341 5180 slave.cpp:637] Already registered with master master@67.195.138.9:55602
> W1015 21:53:12.334908 5180 slave.cpp:637] Already registered with master master@67.195.138.9:55602
> I1015 21:53:12.003942 5176 sched.cpp:281] Authenticating with master master@67.195.138.9: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 master@67.195.138.9: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.2#6252)