You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/04/23 09:10:16 UTC
[jira] [Reopened] (MESOS-743)
ReservationAllocatorTest.ResourcesReturned test is flaky
[ https://issues.apache.org/jira/browse/MESOS-743?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone reopened MESOS-743:
------------------------------
still seems to be having issues.
{code}
[ RUN ] ReservationAllocatorTest.ResourcesReturned
I0423 07:06:59.136368 15213 leveldb.cpp:174] Opened db in 138.313826ms
I0423 07:06:59.156708 15213 leveldb.cpp:181] Compacted db in 20.300896ms
I0423 07:06:59.156764 15213 leveldb.cpp:196] Created db iterator in 12388ns
I0423 07:06:59.156790 15213 leveldb.cpp:202] Seeked to beginning of db in 1358ns
I0423 07:06:59.156805 15213 leveldb.cpp:271] Iterated through 0 keys in the db in 302ns
I0423 07:06:59.156833 15213 replica.cpp:729] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0423 07:06:59.157214 15239 recover.cpp:425] Starting replica recovery
I0423 07:06:59.157645 15251 recover.cpp:451] Replica is in EMPTY status
I0423 07:06:59.159243 15241 master.cpp:264] Master 20140423-070659-1828659978-34834-15213 (smfd-atr-11-sr1.devel.twitter.com) started on 10.35.255.108:34834
I0423 07:06:59.159293 15241 master.cpp:298] Master only allowing authenticated frameworks to register!
W0423 07:06:59.159553 15241 master.cpp:328] Permissions on credentials file '/tmp/ReservationAllocatorTest_ResourcesReturned_lvvzyz/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
I0423 07:06:59.159711 15235 replica.cpp:626] Replica in EMPTY status received a broadcasted recover request
I0423 07:06:59.160047 15236 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0423 07:06:59.161141 15231 recover.cpp:542] Updating replica status to STARTING
I0423 07:06:59.161455 15238 master.cpp:940] The newly elected leader is master@10.35.255.108:34834 with id 20140423-070659-1828659978-34834-15213
I0423 07:06:59.161536 15238 master.cpp:950] Elected as the leading master!
I0423 07:06:59.161573 15238 master.cpp:773] Recovering from registrar
I0423 07:06:59.161747 15248 registrar.cpp:217] Recovering registrar
I0423 07:06:59.203104 15245 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 41.84585ms
I0423 07:06:59.203217 15245 replica.cpp:320] Persisted replica status to STARTING
I0423 07:06:59.203522 15232 recover.cpp:451] Replica is in STARTING status
I0423 07:06:59.205118 15235 replica.cpp:626] Replica in STARTING status received a broadcasted recover request
I0423 07:06:59.205629 15233 recover.cpp:188] Received a recover response from a replica in STARTING status
I0423 07:06:59.206146 15245 recover.cpp:542] Updating replica status to VOTING
I0423 07:06:59.225656 15246 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 18.659086ms
I0423 07:06:59.225709 15246 replica.cpp:320] Persisted replica status to VOTING
I0423 07:06:59.225854 15246 recover.cpp:556] Successfully joined the Paxos group
I0423 07:06:59.226052 15246 recover.cpp:440] Recover process terminated
I0423 07:06:59.226554 15250 log.cpp:651] Attempting to start the writer
I0423 07:06:59.228313 15242 replica.cpp:474] Replica received implicit promise request with proposal 1
I0423 07:06:59.233970 15242 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 5.593814ms
I0423 07:06:59.234020 15242 replica.cpp:342] Persisted promised to 1
I0423 07:06:59.234837 15232 coordinator.cpp:229] Coordinator attemping to fill missing position
I0423 07:06:59.237838 15239 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0423 07:06:59.242300 15239 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 4.378621ms
I0423 07:06:59.242343 15239 replica.cpp:664] Persisted action at 0
I0423 07:06:59.244144 15237 replica.cpp:508] Replica received write request for position 0
I0423 07:06:59.244221 15237 leveldb.cpp:436] Reading position from leveldb took 26388ns
I0423 07:06:59.250630 15237 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 6.367158ms
I0423 07:06:59.250681 15237 replica.cpp:664] Persisted action at 0
I0423 07:06:59.251714 15246 replica.cpp:643] Replica received learned notice for position 0
I0423 07:06:59.258944 15246 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 7.188413ms
I0423 07:06:59.258993 15246 replica.cpp:664] Persisted action at 0
I0423 07:06:59.259023 15246 replica.cpp:649] Replica learned NOP action at position 0
I0423 07:06:59.260048 15232 log.cpp:667] Writer started with ending position 0
I0423 07:06:59.261482 15248 leveldb.cpp:436] Reading position from leveldb took 23410ns
I0423 07:06:59.264057 15242 registrar.cpp:243] Successfully recovered registrar
I0423 07:06:59.264125 15242 registrar.cpp:314] Attempting to update the 'registry'
I0423 07:06:59.266635 15238 log.cpp:675] Attempting to append 155 bytes to the log
I0423 07:06:59.267071 15232 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 1
I0423 07:06:59.269002 15232 replica.cpp:508] Replica received write request for position 1
I0423 07:06:59.275615 15232 leveldb.cpp:341] Persisting action (174 bytes) to leveldb took 6.514845ms
I0423 07:06:59.275661 15232 replica.cpp:664] Persisted action at 1
I0423 07:06:59.276469 15247 replica.cpp:643] Replica received learned notice for position 1
I0423 07:06:59.283948 15247 leveldb.cpp:341] Persisting action (176 bytes) to leveldb took 7.360217ms
I0423 07:06:59.283999 15247 replica.cpp:664] Persisted action at 1
I0423 07:06:59.284034 15247 replica.cpp:649] Replica learned APPEND action at position 1
I0423 07:06:59.284766 15228 registrar.cpp:356] Successfully updated 'registry'
I0423 07:06:59.285089 15246 master.cpp:800] Recovered 0 slaves from the Registry (117B) ; allowing 10mins for slaves to re-register
I0423 07:06:59.285080 15229 log.cpp:694] Attempting to truncate the log to 1
I0423 07:06:59.285506 15236 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 2
I0423 07:06:59.286607 15247 replica.cpp:508] Replica received write request for position 2
I0423 07:06:59.289851 15237 slave.cpp:129] Slave started on 11)@10.35.255.108:34834
I0423 07:06:59.290174 15237 slave.cpp:217] Slave resources: cpus(role1):1; mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1; mem(*):200; disk(*):0; ports(*):[31000-32000]
I0423 07:06:59.290519 15237 slave.cpp:245] Slave hostname: smfd-atr-11-sr1.devel.twitter.com
I0423 07:06:59.290547 15237 slave.cpp:246] Slave checkpoint: false
I0423 07:06:59.291237 15232 state.cpp:33] Recovering state from '/tmp/ReservationAllocatorTest_ResourcesReturned_4xqH6j/meta'
I0423 07:06:59.291550 15232 status_update_manager.cpp:193] Recovering status update manager
I0423 07:06:59.291937 15250 slave.cpp:2791] Finished recovery
I0423 07:06:59.292232 15247 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 5.583508ms
I0423 07:06:59.292279 15247 replica.cpp:664] Persisted action at 2
I0423 07:06:59.292398 15250 slave.cpp:496] New master detected at master@10.35.255.108:34834
I0423 07:06:59.292709 15231 status_update_manager.cpp:167] New master detected at master@10.35.255.108:34834
I0423 07:06:59.292989 15234 replica.cpp:643] Replica received learned notice for position 2
I0423 07:06:59.293023 15250 slave.cpp:521] Detecting new master
I0423 07:06:59.293423 15250 registrar.cpp:314] Attempting to update the 'registry'
I0423 07:06:59.300562 15234 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 7.520354ms
I0423 07:06:59.300634 15234 leveldb.cpp:399] Deleting ~1 keys from leveldb took 29187ns
I0423 07:06:59.300662 15234 replica.cpp:664] Persisted action at 2
I0423 07:06:59.300686 15234 replica.cpp:649] Replica learned TRUNCATE action at position 2
I0423 07:06:59.301554 15243 log.cpp:675] Attempting to append 492 bytes to the log
I0423 07:06:59.301698 15238 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3
I0423 07:06:59.302988 15238 replica.cpp:508] Replica received write request for position 3
I0423 07:06:59.308889 15238 leveldb.cpp:341] Persisting action (511 bytes) to leveldb took 5.859232ms
I0423 07:06:59.308936 15238 replica.cpp:664] Persisted action at 3
I0423 07:06:59.309460 15246 replica.cpp:643] Replica received learned notice for position 3
I0423 07:06:59.317251 15246 leveldb.cpp:341] Persisting action (513 bytes) to leveldb took 7.723017ms
I0423 07:06:59.317348 15246 replica.cpp:664] Persisted action at 3
I0423 07:06:59.317384 15246 replica.cpp:649] Replica learned APPEND action at position 3
I0423 07:06:59.318135 15228 registrar.cpp:356] Successfully updated 'registry'
I0423 07:06:59.318323 15244 log.cpp:694] Attempting to truncate the log to 3
I0423 07:06:59.318536 15250 master.cpp:2150] Admitted slave on smfd-atr-11-sr1.devel.twitter.com at slave(11)@10.35.255.108:34834
I0423 07:06:59.318549 15245 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4
I0423 07:06:59.318586 15250 master.cpp:3204] Adding slave 20140423-070659-1828659978-34834-15213-0 at smfd-atr-11-sr1.devel.twitter.com with cpus(role1):1; mem(role1):200; cpus(role2):2; mem(role2):600; cpus(*):1; mem(*):200; disk(*):0; ports(*):[31000-32000]
I0423 07:06:59.318747 15249 slave.cpp:539] Registered with master master@10.35.255.108:34834; given slave ID 20140423-070659-1828659978-34834-15213-0
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
../../src/tests/mesos.hpp:476:
Function call: slaveAdded(@0x7f1db8012840 20140423-070659-1828659978-34834-15213-0, @0x7f1db8012860 hostname: "smfd-atr-11-sr1.devel.twitter.com"
webui_hostname: "smfd-atr-11-sr1.devel.twitter.com"
resources {
name: "cpus"
type: SCALAR
scalar {
value: 1
}
role: "role1"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 200
}
role: "role1"
}
resources {
name: "cpus"
type: SCALAR
scalar {
value: 2
}
role: "role2"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 600
}
role: "role2"
}
resources {
name: "cpus"
type: SCALAR
scalar {
value: 1
}
role: "*"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 200
}
role: "*"
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 0
}
role: "*"
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
role: "*"
}
id {
value: "20140423-070659-1828659978-34834-15213-0"
I0423 07:06:59.320127 15248 hierarchical_allocator_process.hpp:445] Added slave 20140423-070659-1828659978-34834-15213-0 (smfd-atr-11-sr1.devel.twitter.com) 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)
}
checkpoint: false
port: 34834
, @0x7f1db80128d0 {})
Stack trace:
I0423 07:06:59.320791 15229 replica.cpp:508] Replica received write request for position 4
I0423 07:06:59.324064 15230 slave.cpp:129] Slave started on 12)@10.35.255.108:34834
I0423 07:06:59.324323 15230 slave.cpp:217] Slave resources: cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000]
I0423 07:06:59.324686 15230 slave.cpp:245] Slave hostname: smfd-atr-11-sr1.devel.twitter.com
I0423 07:06:59.324749 15230 slave.cpp:246] Slave checkpoint: false
I0423 07:06:59.325554 15229 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 4.682021ms
I0423 07:06:59.325567 15244 state.cpp:33] Recovering state from '/tmp/ReservationAllocatorTest_ResourcesReturned_HLjtK4/meta'
I0423 07:06:59.325599 15229 replica.cpp:664] Persisted action at 4
I0423 07:06:59.325852 15243 status_update_manager.cpp:193] Recovering status update manager
I0423 07:06:59.326237 15230 replica.cpp:643] Replica received learned notice for position 4
I0423 07:06:59.326282 15231 slave.cpp:2791] Finished recovery
I0423 07:06:59.326664 15244 slave.cpp:496] New master detected at master@10.35.255.108:34834
I0423 07:06:59.326755 15249 status_update_manager.cpp:167] New master detected at master@10.35.255.108:34834
I0423 07:06:59.326803 15244 slave.cpp:521] Detecting new master
I0423 07:06:59.327144 15237 registrar.cpp:314] Attempting to update the 'registry'
I0423 07:06:59.333868 15230 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 7.583842ms
I0423 07:06:59.333946 15230 leveldb.cpp:399] Deleting ~2 keys from leveldb took 35077ns
I0423 07:06:59.333974 15230 replica.cpp:664] Persisted action at 4
I0423 07:06:59.333999 15230 replica.cpp:649] Replica learned TRUNCATE action at position 4
I0423 07:06:59.334805 15247 log.cpp:675] Attempting to append 719 bytes to the log
I0423 07:06:59.334925 15248 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 5
I0423 07:06:59.336089 15249 replica.cpp:508] Replica received write request for position 5
I0423 07:06:59.342200 15249 leveldb.cpp:341] Persisting action (738 bytes) to leveldb took 6.062831ms
I0423 07:06:59.342242 15249 replica.cpp:664] Persisted action at 5
I0423 07:06:59.342746 15238 replica.cpp:643] Replica received learned notice for position 5
I0423 07:06:59.350518 15238 leveldb.cpp:341] Persisting action (740 bytes) to leveldb took 7.739177ms
I0423 07:06:59.350565 15238 replica.cpp:664] Persisted action at 5
I0423 07:06:59.350589 15238 replica.cpp:649] Replica learned APPEND action at position 5
I0423 07:06:59.351433 15243 registrar.cpp:356] Successfully updated 'registry'
I0423 07:06:59.351814 15232 master.cpp:2150] Admitted slave on smfd-atr-11-sr1.devel.twitter.com at slave(12)@10.35.255.108:34834
I0423 07:06:59.351817 15241 log.cpp:694] Attempting to truncate the log to 5
I0423 07:06:59.351848 15232 master.cpp:3204] Adding slave 20140423-070659-1828659978-34834-15213-1 at smfd-atr-11-sr1.devel.twitter.com with cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000]
I0423 07:06:59.351991 15231 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 6
I0423 07:06:59.352092 15243 slave.cpp:539] Registered with master master@10.35.255.108:34834; given slave ID 20140423-070659-1828659978-34834-15213-1
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
../../src/tests/mesos.hpp:476:
Function call: slaveAdded(@0x7f1db8049a50 20140423-070659-1828659978-34834-15213-1, @0x7f1db8049a70 hostname: "smfd-atr-11-sr1.devel.twitter.com"
webui_hostname: "smfd-atr-11-sr1.devel.twitter.com"
resources {
name: "cpus"
type: SCALAR
scalar {
value: 4
}
role: "role3"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 1024
}
role: "*"
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 0
}
role: "*"
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
role: "*"
}
id {
value: "20140423-070659-1828659978-34834-15213-1"
}
checkpoint: false
port: 34834
I0423 07:06:59.352922 15246 hierarchical_allocator_process.hpp:445] Added slave 20140423-070659-1828659978-34834-15213-1 (smfd-atr-11-sr1.devel.twitter.com) with cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000] (and cpus(role3):4; mem(*):1024; disk(*):0; ports(*):[31000-32000] available)
I0423 07:06:59.353101 15240 replica.cpp:508] Replica received write request for position 6
, @0x7f1db8049ae0 {})
Stack trace:
I0423 07:06:59.355746 15213 sched.cpp:121] Version: 0.19.0
I0423 07:06:59.356278 15246 sched.cpp:217] New master detected at master@10.35.255.108:34834
I0423 07:06:59.356366 15246 sched.cpp:268] Authenticating with master master@10.35.255.108:34834
I0423 07:06:59.356501 15242 authenticatee.hpp:128] Creating new client SASL connection
I0423 07:06:59.356637 15238 master.cpp:2715] Authenticating framework at scheduler(8)@10.35.255.108:34834
I0423 07:06:59.356825 15237 authenticator.hpp:148] Creating new server SASL connection
I0423 07:06:59.357000 15230 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0423 07:06:59.357046 15230 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0423 07:06:59.357134 15234 authenticator.hpp:254] Received SASL authentication start
I0423 07:06:59.357195 15234 authenticator.hpp:342] Authentication requires more steps
I0423 07:06:59.357316 15250 authenticatee.hpp:265] Received SASL authentication step
I0423 07:06:59.357447 15250 authenticator.hpp:282] Received SASL authentication step
I0423 07:06:59.357512 15250 authenticator.hpp:334] Authentication success
I0423 07:06:59.357589 15239 authenticatee.hpp:305] Authentication success
I0423 07:06:59.357610 15233 master.cpp:2755] Successfully authenticated framework at scheduler(8)@10.35.255.108:34834
I0423 07:06:59.357902 15243 sched.cpp:342] Successfully authenticated with master master@10.35.255.108:34834
I0423 07:06:59.358043 15243 master.cpp:997] Received registration request from scheduler(8)@10.35.255.108:34834
I0423 07:06:59.358134 15243 master.cpp:1015] Registering framework 20140423-070659-1828659978-34834-15213-0000 at scheduler(8)@10.35.255.108:34834
I0423 07:06:59.358319 15243 sched.cpp:392] Framework registered with 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.358463 15242 hierarchical_allocator_process.hpp:332] Added framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.358844 15240 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 5.65484ms
I0423 07:06:59.358881 15240 replica.cpp:664] Persisted action at 6
I0423 07:06:59.359213 15242 master.cpp:2676] Sending 1 offers to framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.359540 15245 replica.cpp:643] Replica received learned notice for position 6
I0423 07:06:59.361150 15248 master.cpp:1815] Processing reply for offers: [ 20140423-070659-1828659978-34834-15213-0 ] on slave 20140423-070659-1828659978-34834-15213-0 (smfd-atr-11-sr1.devel.twitter.com) for framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.361899 15248 master.hpp:496] Adding task 0 with resources cpus(role1):1; mem(role1):100 on slave 20140423-070659-1828659978-34834-15213-0 (smfd-atr-11-sr1.devel.twitter.com)
I0423 07:06:59.361970 15248 master.cpp:2839] Launching task 0 of framework 20140423-070659-1828659978-34834-15213-0000 with resources cpus(role1):1; mem(role1):100 on slave 20140423-070659-1828659978-34834-15213-0 (smfd-atr-11-sr1.devel.twitter.com)
I0423 07:06:59.362210 15235 slave.cpp:754] Got assigned task 0 for framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.362936 15235 slave.cpp:863] Launching task 0 for framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.363929 15238 master.cpp:2676] Sending 1 offers to framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.367177 15245 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 7.599422ms
I0423 07:06:59.367256 15245 leveldb.cpp:399] Deleting ~2 keys from leveldb took 37160ns
I0423 07:06:59.367295 15245 replica.cpp:664] Persisted action at 6
I0423 07:06:59.367333 15245 replica.cpp:649] Replica learned TRUNCATE action at position 6
I0423 07:06:59.367758 15235 exec.cpp:131] Version: 0.19.0
I0423 07:06:59.368712 15235 slave.cpp:973] Queuing task '0' for executor default of framework '20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.368974 15235 slave.cpp:1446] Got registration for executor 'default' of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.369413 15235 slave.cpp:1565] Flushing queued task 0 for executor 'default' of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.369556 15248 exec.cpp:205] Executor registered on slave 20140423-070659-1828659978-34834-15213-0
I0423 07:06:59.369639 15235 slave.cpp:2118] Monitoring executor 'default' of framework '20140423-070659-1828659978-34834-15213-0000' in container '49eb2958-0c67-47f0-9f18-893d62a80bc4'
I0423 07:06:59.374025 15248 slave.cpp:1775] Handling status update TASK_RUNNING (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 from executor(1)@10.35.255.108:34834
I0423 07:06:59.374372 15246 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.374758 15246 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 to master@10.35.255.108:34834
I0423 07:06:59.375046 15213 sched.cpp:121] Version: 0.19.0
I0423 07:06:59.375114 15228 slave.cpp:1898] Sending acknowledgement for status update TASK_RUNNING (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 to executor(1)@10.35.255.108:34834
I0423 07:06:59.375154 15231 master.cpp:2382] Status update TASK_RUNNING (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 from slave(11)@10.35.255.108:34834
I0423 07:06:59.375572 15246 sched.cpp:217] New master detected at master@10.35.255.108:34834
I0423 07:06:59.375743 15246 sched.cpp:268] Authenticating with master master@10.35.255.108:34834
I0423 07:06:59.375813 15247 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 09b96f78-2d48-48bc-9807-046df91b2672) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.376096 15232 authenticatee.hpp:128] Creating new client SASL connection
I0423 07:06:59.376266 15242 master.cpp:2715] Authenticating framework at scheduler(9)@10.35.255.108:34834
I0423 07:06:59.376442 15233 authenticator.hpp:148] Creating new server SASL connection
I0423 07:06:59.376610 15244 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0423 07:06:59.376654 15244 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0423 07:06:59.376741 15232 authenticator.hpp:254] Received SASL authentication start
I0423 07:06:59.376816 15232 authenticator.hpp:342] Authentication requires more steps
I0423 07:06:59.376945 15236 authenticatee.hpp:265] Received SASL authentication step
I0423 07:06:59.377068 15237 authenticator.hpp:282] Received SASL authentication step
I0423 07:06:59.377149 15237 authenticator.hpp:334] Authentication success
I0423 07:06:59.377249 15243 authenticatee.hpp:305] Authentication success
I0423 07:06:59.377305 15236 master.cpp:2755] Successfully authenticated framework at scheduler(9)@10.35.255.108:34834
I0423 07:06:59.377586 15244 sched.cpp:342] Successfully authenticated with master master@10.35.255.108:34834
I0423 07:06:59.377729 15244 master.cpp:997] Received registration request from scheduler(9)@10.35.255.108:34834
I0423 07:06:59.377804 15244 master.cpp:1015] Registering framework 20140423-070659-1828659978-34834-15213-0001 at scheduler(9)@10.35.255.108:34834
I0423 07:06:59.377974 15244 sched.cpp:392] Framework registered with 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.378115 15234 hierarchical_allocator_process.hpp:332] Added framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.378597 15243 master.cpp:2676] Sending 1 offers to framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.381088 15241 slave.cpp:1775] Handling status update TASK_FINISHED (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 from executor(1)@10.35.255.108:34834
I0423 07:06:59.381381 15239 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.381469 15239 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 to master@10.35.255.108:34834
I0423 07:06:59.381710 15237 slave.cpp:1898] Sending acknowledgement for status update TASK_FINISHED (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 to executor(1)@10.35.255.108:34834
I0423 07:06:59.381809 15244 master.cpp:2382] Status update TASK_FINISHED (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000 from slave(11)@10.35.255.108:34834
I0423 07:06:59.382071 15244 master.hpp:514] Removing task 0 with resources cpus(role1):1; mem(role1):100 on slave 20140423-070659-1828659978-34834-15213-0 (smfd-atr-11-sr1.devel.twitter.com)
I0423 07:06:59.382133 15246 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 6c4f2929-c5e9-472c-b3f2-3db7926c7617) for task 0 of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.382448 15251 hierarchical_allocator_process.hpp:637] Recovered cpus(role1):1; mem(role1):100 (total allocatable: cpus(role1):1; mem(role1):100) on slave 20140423-070659-1828659978-34834-15213-0 from framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.415477 15248 master.cpp:2676] Sending 1 offers to framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.416295 15242 sched.cpp:731] Stopping framework '20140423-070659-1828659978-34834-15213-0001'
I0423 07:06:59.416348 15238 sched.cpp:731] Stopping framework '20140423-070659-1828659978-34834-15213-0000'
I0423 07:06:59.416497 15234 master.cpp:1207] Asked to unregister framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.416542 15234 master.cpp:3074] Removing framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.416837 15243 slave.cpp:1157] Asked to shut down framework 20140423-070659-1828659978-34834-15213-0001 by master@10.35.255.108:34834
I0423 07:06:59.416847 15251 slave.cpp:1157] Asked to shut down framework 20140423-070659-1828659978-34834-15213-0001 by master@10.35.255.108:34834
W0423 07:06:59.416925 15243 slave.cpp:1172] Cannot shut down unknown framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.416946 15240 hierarchical_allocator_process.hpp:408] Deactivated framework 20140423-070659-1828659978-34834-15213-0001
W0423 07:06:59.417096 15251 slave.cpp:1172] Cannot shut down unknown framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.417439 15233 hierarchical_allocator_process.hpp:637] Recovered cpus(role2):2; mem(role2):600 (total allocatable: cpus(role2):2; mem(role2):600) on slave 20140423-070659-1828659978-34834-15213-0 from framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.417613 15234 master.cpp:1207] Asked to unregister framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.417654 15234 master.cpp:3074] Removing framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.417702 15233 hierarchical_allocator_process.hpp:363] Removed framework 20140423-070659-1828659978-34834-15213-0001
I0423 07:06:59.417784 15228 slave.cpp:1157] Asked to shut down framework 20140423-070659-1828659978-34834-15213-0000 by master@10.35.255.108:34834
I0423 07:06:59.417809 15245 slave.cpp:1157] Asked to shut down framework 20140423-070659-1828659978-34834-15213-0000 by master@10.35.255.108:34834
W0423 07:06:59.417825 15228 slave.cpp:1172] Cannot shut down unknown framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.417857 15245 slave.cpp:1182] Shutting down framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.417867 15248 hierarchical_allocator_process.hpp:408] Deactivated framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.418001 15245 slave.cpp:2461] Shutting down executor 'default' of framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.418117 15242 exec.cpp:378] Executor asked to shutdown
I0423 07:06:59.418201 15231 hierarchical_allocator_process.hpp:637] Recovered cpus(role1):1; mem(role1):100 (total allocatable: cpus(role2):2; mem(role2):600; cpus(role1):1; mem(role1):100) on slave 20140423-070659-1828659978-34834-15213-0 from framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.418668 15251 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):200; ports(*):[31000-32000]; mem(role1):100 (total allocatable: cpus(role2):2; mem(role2):600; cpus(role1):1; mem(role1):200; cpus(*):1; mem(*):200; disk(*):0; ports(*):[31000-32000]) on slave 20140423-070659-1828659978-34834-15213-0 from framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.418719 15234 master.cpp:573] Master terminating
I0423 07:06:59.418800 15251 hierarchical_allocator_process.hpp:363] Removed framework 20140423-070659-1828659978-34834-15213-0000
I0423 07:06:59.419327 15242 slave.cpp:1973] master@10.35.255.108:34834 exited
W0423 07:06:59.419369 15242 slave.cpp:1976] Master disconnected! Waiting for a new master to be elected
I0423 07:06:59.419380 15232 slave.cpp:1973] master@10.35.255.108:34834 exited
W0423 07:06:59.419419 15232 slave.cpp:1976] Master disconnected! Waiting for a new master to be elected
I0423 07:06:59.421110 15240 slave.cpp:386] Slave terminating
I0423 07:06:59.421248 15240 slave.cpp:1157] Asked to shut down framework 20140423-070659-1828659978-34834-15213-0000 by @0.0.0.0:0
W0423 07:06:59.421298 15240 slave.cpp:1178] Ignoring shutdown framework 20140423-070659-1828659978-34834-15213-0000 because it is terminating
I0423 07:06:59.422312 15238 slave.cpp:386] Slave terminating
[ OK ] ReservationAllocatorTest.ResourcesReturned (427 ms)
[----------] 2 tests from ReservationAllocatorTest (862 ms total)
{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
> 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)