mesos-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Vinod Kone (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (MESOS-743) ReservationAllocatorTest.ResourcesReturned test is flaky
Date Thu, 17 Apr 2014 17:17:16 GMT

    [ https://issues.apache.org/jira/browse/MESOS-743?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13973153#comment-13973153
] 

Vinod Kone commented on MESOS-743:
----------------------------------

A different error for the same test

{code}
[ RUN      ] ReservationAllocatorTest.ResourcesReturned
tests/allocator_tests.cpp:523: Failure
Actual function call count doesn't match EXPECT_CALL(allocator, slaveAdded(_, _, _))...
         Expected: to be called twice
           Actual: called once - unsatisfied and active
[  FAILED  ] ReservationAllocatorTest.ResourcesReturned (395 ms)
{code}

> 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.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)

Mime
View raw message