Vinod Kone created MESOS-1814:
---------------------------------

             Summary: Task attempted to use more offers than requested in 
example framework
                 Key: MESOS-1814
                 URL: https://issues.apache.org/jira/browse/MESOS-1814
             Project: Mesos
          Issue Type: Bug
            Reporter: Vinod Kone


{code}
[ RUN      ] ExamplesTest.JavaFramework
Using temporary directory '/tmp/ExamplesTest_JavaFramework_2PcFCh'
Enabling authentication for the framework
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0917 23:14:35.199069 31510 process.cpp:1771] libprocess is initialized on 
127.0.1.1:34609 for 8 cpus
I0917 23:14:35.199794 31510 logging.cpp:177] Logging to STDERR
I0917 23:14:35.225342 31510 leveldb.cpp:176] Opened db in 22.197149ms
I0917 23:14:35.231133 31510 leveldb.cpp:183] Compacted db in 5.601897ms
I0917 23:14:35.231498 31510 leveldb.cpp:198] Created db iterator in 215441ns
I0917 23:14:35.231608 31510 leveldb.cpp:204] Seeked to beginning of db in 
11488ns
I0917 23:14:35.231722 31510 leveldb.cpp:273] Iterated through 0 keys in the db 
in 14016ns
I0917 23:14:35.231917 31510 replica.cpp:741] Replica recovered with log 
positions 0 -> 0 with 1 holes and 0 unlearned
I0917 23:14:35.233129 31526 recover.cpp:425] Starting replica recovery
I0917 23:14:35.233614 31526 recover.cpp:451] Replica is in EMPTY status
I0917 23:14:35.234994 31526 replica.cpp:638] Replica in EMPTY status received a 
broadcasted recover request
I0917 23:14:35.240116 31519 recover.cpp:188] Received a recover response from a 
replica in EMPTY status
I0917 23:14:35.240782 31519 recover.cpp:542] Updating replica status to STARTING
I0917 23:14:35.242846 31524 master.cpp:286] Master 
20140917-231435-16842879-34609-31503 (saucy) started on 127.0.1.1:34609
I0917 23:14:35.243191 31524 master.cpp:332] Master only allowing authenticated 
frameworks to register
I0917 23:14:35.243288 31524 master.cpp:339] Master allowing unauthenticated 
slaves to register
I0917 23:14:35.243399 31524 credentials.hpp:36] Loading credentials for 
authentication from '/tmp/ExamplesTest_JavaFramework_2PcFCh/credentials'
W0917 23:14:35.243588 31524 credentials.hpp:51] Permissions on credentials file 
'/tmp/ExamplesTest_JavaFramework_2PcFCh/credentials' are too open. It is 
recommended that your credentials file is NOT accessible by others.
I0917 23:14:35.243846 31524 master.cpp:366] Authorization enabled
I0917 23:14:35.244882 31520 hierarchical_allocator_process.hpp:299] 
Initializing hierarchical allocator process with master : master@127.0.1.1:34609
I0917 23:14:35.245224 31520 master.cpp:120] No whitelist given. Advertising 
offers for all slaves
I0917 23:14:35.246934 31524 master.cpp:1211] The newly elected leader is 
master@127.0.1.1:34609 with id 20140917-231435-16842879-34609-31503
I0917 23:14:35.247234 31524 master.cpp:1224] Elected as the leading master!
I0917 23:14:35.247336 31524 master.cpp:1042] Recovering from registrar
I0917 23:14:35.247542 31526 registrar.cpp:313] Recovering registrar
I0917 23:14:35.250555 31510 containerizer.cpp:89] Using isolation: 
posix/cpu,posix/mem
I0917 23:14:35.252326 31510 containerizer.cpp:89] Using isolation: 
posix/cpu,posix/mem
I0917 23:14:35.252821 31520 slave.cpp:169] Slave started on 1)@127.0.1.1:34609
I0917 23:14:35.253552 31520 slave.cpp:289] Slave resources: cpus(*):1; 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:35.253906 31520 slave.cpp:317] Slave hostname: saucy
I0917 23:14:35.254004 31520 slave.cpp:318] Slave checkpoint: true
I0917 23:14:35.254818 31520 state.cpp:33] Recovering state from 
'/tmp/mesos-w8snRW/0/meta'
I0917 23:14:35.255106 31519 leveldb.cpp:306] Persisting metadata (8 bytes) to 
leveldb took 13.99622ms
I0917 23:14:35.255235 31519 replica.cpp:320] Persisted replica status to 
STARTING
I0917 23:14:35.255419 31519 recover.cpp:451] Replica is in STARTING status
I0917 23:14:35.255834 31519 replica.cpp:638] Replica in STARTING status 
received a broadcasted recover request
I0917 23:14:35.256000 31519 recover.cpp:188] Received a recover response from a 
replica in STARTING status
I0917 23:14:35.256217 31519 recover.cpp:542] Updating replica status to VOTING
I0917 23:14:35.256641 31520 status_update_manager.cpp:193] Recovering status 
update manager
I0917 23:14:35.257064 31520 containerizer.cpp:252] Recovering containerizer
I0917 23:14:35.257725 31520 slave.cpp:3220] Finished recovery
I0917 23:14:35.258463 31520 slave.cpp:600] New master detected at 
master@127.0.1.1:34609
I0917 23:14:35.258769 31524 status_update_manager.cpp:167] New master detected 
at master@127.0.1.1:34609
I0917 23:14:35.258885 31520 slave.cpp:636] No credentials provided. Attempting 
to register without authentication
I0917 23:14:35.259024 31520 slave.cpp:647] Detecting new master
I0917 23:14:35.259863 31520 slave.cpp:169] Slave started on 2)@127.0.1.1:34609
I0917 23:14:35.260288 31520 slave.cpp:289] Slave resources: cpus(*):1; 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:35.260493 31520 slave.cpp:317] Slave hostname: saucy
I0917 23:14:35.260588 31520 slave.cpp:318] Slave checkpoint: true
I0917 23:14:35.265127 31510 containerizer.cpp:89] Using isolation: 
posix/cpu,posix/mem
I0917 23:14:35.265877 31519 leveldb.cpp:306] Persisting metadata (8 bytes) to 
leveldb took 9.536278ms
I0917 23:14:35.265983 31519 replica.cpp:320] Persisted replica status to VOTING
I0917 23:14:35.266324 31519 recover.cpp:556] Successfully joined the Paxos group
I0917 23:14:35.266511 31519 recover.cpp:440] Recover process terminated
I0917 23:14:35.266978 31519 log.cpp:656] Attempting to start the writer
I0917 23:14:35.268165 31523 replica.cpp:474] Replica received implicit promise 
request with proposal 1
I0917 23:14:35.269850 31525 slave.cpp:169] Slave started on 3)@127.0.1.1:34609
I0917 23:14:35.270365 31525 slave.cpp:289] Slave resources: cpus(*):1; 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:35.270658 31525 slave.cpp:317] Slave hostname: saucy
I0917 23:14:35.270781 31525 slave.cpp:318] Slave checkpoint: true
I0917 23:14:35.271332 31525 state.cpp:33] Recovering state from 
'/tmp/mesos-w8snRW/2/meta'
I0917 23:14:35.271580 31522 status_update_manager.cpp:193] Recovering status 
update manager
I0917 23:14:35.271838 31522 containerizer.cpp:252] Recovering containerizer
I0917 23:14:35.272238 31525 slave.cpp:3220] Finished recovery
I0917 23:14:35.273002 31525 slave.cpp:600] New master detected at 
master@127.0.1.1:34609
I0917 23:14:35.273252 31521 status_update_manager.cpp:167] New master detected 
at master@127.0.1.1:34609
I0917 23:14:35.273360 31525 slave.cpp:636] No credentials provided. Attempting 
to register without authentication
I0917 23:14:35.273507 31525 slave.cpp:647] Detecting new master
I0917 23:14:35.275413 31525 state.cpp:33] Recovering state from 
'/tmp/mesos-w8snRW/1/meta'
I0917 23:14:35.278506 31523 leveldb.cpp:306] Persisting metadata (8 bytes) to 
leveldb took 10.232514ms
I0917 23:14:35.278712 31523 replica.cpp:342] Persisted promised to 1
I0917 23:14:35.279585 31523 coordinator.cpp:230] Coordinator attemping to fill 
missing position
I0917 23:14:35.280400 31523 replica.cpp:375] Replica received explicit promise 
request for position 0 with proposal 2
I0917 23:14:35.280900 31526 status_update_manager.cpp:193] Recovering status 
update manager
I0917 23:14:35.281282 31519 containerizer.cpp:252] Recovering containerizer
I0917 23:14:35.281615 31520 slave.cpp:3220] Finished recovery
I0917 23:14:35.281891 31510 sched.cpp:137] Version: 0.21.0
I0917 23:14:35.282306 31526 sched.cpp:233] New master detected at 
master@127.0.1.1:34609
I0917 23:14:35.282464 31526 sched.cpp:283] Authenticating with master 
master@127.0.1.1:34609
I0917 23:14:35.282891 31526 authenticatee.hpp:104] Initializing client SASL
I0917 23:14:35.284816 31526 authenticatee.hpp:128] Creating new client SASL 
connection
I0917 23:14:35.285428 31519 master.cpp:873] Dropping 
'mesos.internal.AuthenticateMessage' message since not recovered yet
I0917 23:14:35.288007 31521 slave.cpp:600] New master detected at 
master@127.0.1.1:34609
I0917 23:14:35.288399 31521 slave.cpp:636] No credentials provided. Attempting 
to register without authentication
I0917 23:14:35.288535 31521 slave.cpp:647] Detecting new master
I0917 23:14:35.288501 31519 status_update_manager.cpp:167] New master detected 
at master@127.0.1.1:34609
I0917 23:14:35.289625 31523 leveldb.cpp:343] Persisting action (8 bytes) to 
leveldb took 8.997343ms
I0917 23:14:35.289784 31523 replica.cpp:676] Persisted action at 0
I0917 23:14:35.292667 31521 replica.cpp:508] Replica received write request for 
position 0
I0917 23:14:35.293112 31521 leveldb.cpp:438] Reading position from leveldb took 
325638ns
I0917 23:14:35.301774 31521 leveldb.cpp:343] Persisting action (14 bytes) to 
leveldb took 8.576338ms
I0917 23:14:35.301916 31521 replica.cpp:676] Persisted action at 0
I0917 23:14:35.302289 31521 replica.cpp:655] Replica received learned notice 
for position 0
I0917 23:14:35.310542 31521 leveldb.cpp:343] Persisting action (16 bytes) to 
leveldb took 8.087789ms
I0917 23:14:35.310675 31521 replica.cpp:676] Persisted action at 0
I0917 23:14:35.310946 31521 replica.cpp:661] Replica learned NOP action at 
position 0
I0917 23:14:35.311254 31521 log.cpp:672] Writer started with ending position 0
I0917 23:14:35.311957 31521 leveldb.cpp:438] Reading position from leveldb took 
35110ns
I0917 23:14:35.320283 31521 registrar.cpp:346] Successfully fetched the 
registry (0B)
I0917 23:14:35.320513 31521 registrar.cpp:422] Attempting to update the 
'registry'
I0917 23:14:35.322226 31525 log.cpp:680] Attempting to append 118 bytes to the 
log
I0917 23:14:35.322549 31525 coordinator.cpp:340] Coordinator attempting to 
write APPEND action at position 1
I0917 23:14:35.322931 31525 replica.cpp:508] Replica received write request for 
position 1
I0917 23:14:35.330169 31525 leveldb.cpp:343] Persisting action (135 bytes) to 
leveldb took 7.133053ms
I0917 23:14:35.330340 31525 replica.cpp:676] Persisted action at 1
I0917 23:14:35.330890 31525 replica.cpp:655] Replica received learned notice 
for position 1
I0917 23:14:35.339218 31525 leveldb.cpp:343] Persisting action (137 bytes) to 
leveldb took 8.192024ms
I0917 23:14:35.339380 31525 replica.cpp:676] Persisted action at 1
I0917 23:14:35.339715 31525 replica.cpp:661] Replica learned APPEND action at 
position 1
I0917 23:14:35.340615 31525 registrar.cpp:479] Successfully updated 'registry'
I0917 23:14:35.340802 31525 registrar.cpp:372] Successfully recovered registrar
I0917 23:14:35.341104 31525 log.cpp:699] Attempting to truncate the log to 1
I0917 23:14:35.341351 31525 master.cpp:1069] Recovered 0 slaves from the 
Registry (82B) ; allowing 10mins for slaves to re-register
I0917 23:14:35.341527 31525 coordinator.cpp:340] Coordinator attempting to 
write TRUNCATE action at position 2
I0917 23:14:35.341964 31525 replica.cpp:508] Replica received write request for 
position 2
I0917 23:14:35.352336 31525 leveldb.cpp:343] Persisting action (16 bytes) to 
leveldb took 10.213086ms
I0917 23:14:35.352494 31525 replica.cpp:676] Persisted action at 2
I0917 23:14:35.356258 31523 replica.cpp:655] Replica received learned notice 
for position 2
I0917 23:14:35.364992 31523 leveldb.cpp:343] Persisting action (18 bytes) to 
leveldb took 8.606522ms
I0917 23:14:35.365166 31523 leveldb.cpp:401] Deleting ~1 keys from leveldb took 
48378ns
I0917 23:14:35.365404 31523 replica.cpp:676] Persisted action at 2
I0917 23:14:35.365537 31523 replica.cpp:661] Replica learned TRUNCATE action at 
position 2
I0917 23:14:35.568366 31523 slave.cpp:994] Will retry registration in 
423.208575ms if necessary
I0917 23:14:35.568840 31522 master.cpp:2870] Registering slave at 
slave(3)@127.0.1.1:34609 (saucy) with id 20140917-231435-16842879-34609-31503-0
I0917 23:14:35.569422 31522 registrar.cpp:422] Attempting to update the 
'registry'
I0917 23:14:35.572013 31522 log.cpp:680] Attempting to append 289 bytes to the 
log
I0917 23:14:35.572273 31519 coordinator.cpp:340] Coordinator attempting to 
write APPEND action at position 3
I0917 23:14:35.572816 31519 replica.cpp:508] Replica received write request for 
position 3
I0917 23:14:35.579784 31519 leveldb.cpp:343] Persisting action (308 bytes) to 
leveldb took 6.809365ms
I0917 23:14:35.579907 31519 replica.cpp:676] Persisted action at 3
I0917 23:14:35.580512 31519 replica.cpp:655] Replica received learned notice 
for position 3
I0917 23:14:35.588748 31519 leveldb.cpp:343] Persisting action (310 bytes) to 
leveldb took 8.112519ms
I0917 23:14:35.588888 31519 replica.cpp:676] Persisted action at 3
I0917 23:14:35.588985 31519 replica.cpp:661] Replica learned APPEND action at 
position 3
I0917 23:14:35.589754 31519 registrar.cpp:479] Successfully updated 'registry'
I0917 23:14:35.590070 31519 master.cpp:2910] Registered slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
I0917 23:14:35.590255 31519 master.cpp:4118] Adding slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) with 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:35.590831 31519 slave.cpp:765] Registered with master 
master@127.0.1.1:34609; given slave ID 20140917-231435-16842879-34609-31503-0
I0917 23:14:35.589913 31523 log.cpp:699] Attempting to truncate the log to 3
I0917 23:14:35.591414 31523 coordinator.cpp:340] Coordinator attempting to 
write TRUNCATE action at position 4
I0917 23:14:35.591815 31523 replica.cpp:508] Replica received write request for 
position 4
I0917 23:14:35.591117 31521 hierarchical_allocator_process.hpp:442] Added slave 
20140917-231435-16842879-34609-31503-0 (saucy) with cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] available)
I0917 23:14:35.592293 31521 hierarchical_allocator_process.hpp:679] Performed 
allocation for slave 20140917-231435-16842879-34609-31503-0 in 64364ns
I0917 23:14:35.592953 31519 slave.cpp:778] Checkpointing SlaveInfo to 
'/tmp/mesos-w8snRW/2/meta/slaves/20140917-231435-16842879-34609-31503-0/slave.info'
I0917 23:14:35.593475 31519 slave.cpp:2347] Received ping from 
slave-observer(1)@127.0.1.1:34609
I0917 23:14:35.601356 31523 leveldb.cpp:343] Persisting action (16 bytes) to 
leveldb took 9.420461ms
I0917 23:14:35.601539 31523 replica.cpp:676] Persisted action at 4
I0917 23:14:35.602325 31523 replica.cpp:655] Replica received learned notice 
for position 4
I0917 23:14:35.610779 31523 leveldb.cpp:343] Persisting action (18 bytes) to 
leveldb took 8.34398ms
I0917 23:14:35.611114 31523 leveldb.cpp:401] Deleting ~2 keys from leveldb took 
66521ns
I0917 23:14:35.611554 31523 replica.cpp:676] Persisted action at 4
I0917 23:14:35.611690 31523 replica.cpp:661] Replica learned TRUNCATE action at 
position 4
I0917 23:14:36.033941 31523 slave.cpp:994] Will retry registration in 
322.705631ms if necessary
I0917 23:14:36.034276 31521 master.cpp:2870] Registering slave at 
slave(1)@127.0.1.1:34609 (saucy) with id 20140917-231435-16842879-34609-31503-1
I0917 23:14:36.034536 31521 registrar.cpp:422] Attempting to update the 
'registry'
I0917 23:14:36.035889 31521 log.cpp:680] Attempting to append 454 bytes to the 
log
I0917 23:14:36.036099 31524 coordinator.cpp:340] Coordinator attempting to 
write APPEND action at position 5
I0917 23:14:36.036416 31524 replica.cpp:508] Replica received write request for 
position 5
I0917 23:14:36.046672 31524 leveldb.cpp:343] Persisting action (473 bytes) to 
leveldb took 10.160627ms
I0917 23:14:36.047035 31524 replica.cpp:676] Persisted action at 5
I0917 23:14:36.047613 31524 replica.cpp:655] Replica received learned notice 
for position 5
I0917 23:14:36.053006 31524 leveldb.cpp:343] Persisting action (475 bytes) to 
leveldb took 5.180742ms
I0917 23:14:36.053246 31524 replica.cpp:676] Persisted action at 5
I0917 23:14:36.053678 31524 replica.cpp:661] Replica learned APPEND action at 
position 5
I0917 23:14:36.060384 31524 registrar.cpp:479] Successfully updated 'registry'
I0917 23:14:36.061328 31524 master.cpp:2910] Registered slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
I0917 23:14:36.061537 31524 master.cpp:4118] Adding slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) with 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:36.061982 31524 slave.cpp:765] Registered with master 
master@127.0.1.1:34609; given slave ID 20140917-231435-16842879-34609-31503-1
I0917 23:14:36.062891 31524 slave.cpp:778] Checkpointing SlaveInfo to 
'/tmp/mesos-w8snRW/0/meta/slaves/20140917-231435-16842879-34609-31503-1/slave.info'
I0917 23:14:36.061050 31525 log.cpp:699] Attempting to truncate the log to 5
I0917 23:14:36.063244 31525 coordinator.cpp:340] Coordinator attempting to 
write TRUNCATE action at position 6
I0917 23:14:36.063746 31525 replica.cpp:508] Replica received write request for 
position 6
I0917 23:14:36.062386 31520 hierarchical_allocator_process.hpp:442] Added slave 
20140917-231435-16842879-34609-31503-1 (saucy) with cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] available)
I0917 23:14:36.064352 31520 hierarchical_allocator_process.hpp:679] Performed 
allocation for slave 20140917-231435-16842879-34609-31503-1 in 35730ns
I0917 23:14:36.065166 31524 slave.cpp:2347] Received ping from 
slave-observer(2)@127.0.1.1:34609
I0917 23:14:36.070137 31525 leveldb.cpp:343] Persisting action (16 bytes) to 
leveldb took 6.242192ms
I0917 23:14:36.070355 31525 replica.cpp:676] Persisted action at 6
I0917 23:14:36.071005 31525 replica.cpp:655] Replica received learned notice 
for position 6
I0917 23:14:36.076560 31525 leveldb.cpp:343] Persisting action (18 bytes) to 
leveldb took 5.368532ms
I0917 23:14:36.077137 31525 leveldb.cpp:401] Deleting ~2 keys from leveldb took 
371245ns
I0917 23:14:36.077241 31525 replica.cpp:676] Persisted action at 6
I0917 23:14:36.077345 31525 replica.cpp:661] Replica learned TRUNCATE action at 
position 6
I0917 23:14:36.141270 31522 slave.cpp:994] Will retry registration in 
1.857205901secs if necessary
I0917 23:14:36.141644 31522 master.cpp:2870] Registering slave at 
slave(2)@127.0.1.1:34609 (saucy) with id 20140917-231435-16842879-34609-31503-2
I0917 23:14:36.141930 31522 registrar.cpp:422] Attempting to update the 
'registry'
I0917 23:14:36.143316 31521 log.cpp:680] Attempting to append 619 bytes to the 
log
I0917 23:14:36.143646 31521 coordinator.cpp:340] Coordinator attempting to 
write APPEND action at position 7
I0917 23:14:36.143954 31521 replica.cpp:508] Replica received write request for 
position 7
I0917 23:14:36.148875 31521 leveldb.cpp:343] Persisting action (638 bytes) to 
leveldb took 4.787834ms
I0917 23:14:36.149085 31521 replica.cpp:676] Persisted action at 7
I0917 23:14:36.149673 31521 replica.cpp:655] Replica received learned notice 
for position 7
I0917 23:14:36.155232 31521 leveldb.cpp:343] Persisting action (640 bytes) to 
leveldb took 5.472209ms
I0917 23:14:36.155522 31521 replica.cpp:676] Persisted action at 7
I0917 23:14:36.155936 31521 replica.cpp:661] Replica learned APPEND action at 
position 7
I0917 23:14:36.156481 31521 registrar.cpp:479] Successfully updated 'registry'
I0917 23:14:36.156663 31526 log.cpp:699] Attempting to truncate the log to 7
I0917 23:14:36.156813 31526 coordinator.cpp:340] Coordinator attempting to 
write TRUNCATE action at position 8
I0917 23:14:36.157155 31526 replica.cpp:508] Replica received write request for 
position 8
I0917 23:14:36.157510 31520 master.cpp:2910] Registered slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:36.157645 31520 master.cpp:4118] Adding slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) with 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000]
I0917 23:14:36.157928 31520 slave.cpp:765] Registered with master 
master@127.0.1.1:34609; given slave ID 20140917-231435-16842879-34609-31503-2
I0917 23:14:36.158304 31520 slave.cpp:778] Checkpointing SlaveInfo to 
'/tmp/mesos-w8snRW/1/meta/slaves/20140917-231435-16842879-34609-31503-2/slave.info'
I0917 23:14:36.158685 31520 hierarchical_allocator_process.hpp:442] Added slave 
20140917-231435-16842879-34609-31503-2 (saucy) with cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] available)
I0917 23:14:36.158821 31520 hierarchical_allocator_process.hpp:679] Performed 
allocation for slave 20140917-231435-16842879-34609-31503-2 in 23287ns
I0917 23:14:36.158965 31520 slave.cpp:2347] Received ping from 
slave-observer(3)@127.0.1.1:34609
I0917 23:14:36.167183 31526 leveldb.cpp:343] Persisting action (16 bytes) to 
leveldb took 9.894561ms
I0917 23:14:36.167323 31526 replica.cpp:676] Persisted action at 8
I0917 23:14:36.167765 31526 replica.cpp:655] Replica received learned notice 
for position 8
I0917 23:14:36.177480 31526 leveldb.cpp:343] Persisting action (18 bytes) to 
leveldb took 9.585411ms
I0917 23:14:36.177675 31526 leveldb.cpp:401] Deleting ~2 keys from leveldb took 
37564ns
I0917 23:14:36.177973 31526 replica.cpp:676] Persisted action at 8
I0917 23:14:36.178089 31526 replica.cpp:661] Replica learned TRUNCATE action at 
position 8
I0917 23:14:36.245735 31526 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 96108ns
I0917 23:14:37.246182 31519 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 83121ns
I0917 23:14:38.246640 31519 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 126479ns
I0917 23:14:39.247378 31526 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 81524ns
I0917 23:14:39.895262 31488 exec.cpp:86] Committing suicide by killing the 
process group
I0917 23:14:39.900475 31494 exec.cpp:86] Committing suicide by killing the 
process group
I0917 23:14:39.904479 31482 exec.cpp:86] Committing suicide by killing the 
process group
I0917 23:14:40.246654 31520 master.cpp:120] No whitelist given. Advertising 
offers for all slaves
I0917 23:14:40.247879 31524 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 84970ns
W0917 23:14:40.283375 31522 sched.cpp:378] Authentication timed out
I0917 23:14:40.283819 31522 sched.cpp:338] Failed to authenticate with master 
master@127.0.1.1:34609: Authentication discarded
I0917 23:14:40.283980 31522 sched.cpp:283] Authenticating with master 
master@127.0.1.1:34609
I0917 23:14:40.284317 31522 authenticatee.hpp:128] Creating new client SASL 
connection
I0917 23:14:40.284855 31522 master.cpp:3669] Authenticating 
scheduler-4c79cf12-ea1b-49e5-bae1-d34f91605227@127.0.1.1:34609
I0917 23:14:40.285302 31522 authenticator.hpp:94] Initializing server SASL
I0917 23:14:40.285907 31522 auxprop.cpp:45] Initialized in-memory auxiliary 
property plugin
I0917 23:14:40.286022 31522 authenticator.hpp:156] Creating new server SASL 
connection
I0917 23:14:40.286351 31525 authenticatee.hpp:219] Received SASL authentication 
mechanisms: CRAM-MD5
I0917 23:14:40.286486 31525 authenticatee.hpp:245] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0917 23:14:40.286731 31522 authenticator.hpp:262] Received SASL authentication 
start
I0917 23:14:40.286923 31522 authenticator.hpp:384] Authentication requires more 
steps
I0917 23:14:40.287080 31524 authenticatee.hpp:265] Received SASL authentication 
step
I0917 23:14:40.287230 31522 authenticator.hpp:290] Received SASL authentication 
step
I0917 23:14:40.287385 31522 auxprop.cpp:81] Request to lookup properties for 
user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0917 23:14:40.287508 31522 auxprop.cpp:153] Looking up auxiliary property 
'*userPassword'
I0917 23:14:40.287664 31522 auxprop.cpp:153] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0917 23:14:40.287777 31522 auxprop.cpp:81] Request to lookup properties for 
user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0917 23:14:40.287912 31522 auxprop.cpp:103] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0917 23:14:40.288020 31522 auxprop.cpp:103] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0917 23:14:40.288214 31522 authenticator.hpp:376] Authentication success
I0917 23:14:40.288396 31526 authenticatee.hpp:305] Authentication success
I0917 23:14:40.291566 31526 sched.cpp:357] Successfully authenticated with 
master master@127.0.1.1:34609
I0917 23:14:40.291960 31521 master.cpp:3709] Successfully authenticated 
principal 'test-principal' at 
scheduler-4c79cf12-ea1b-49e5-bae1-d34f91605227@127.0.1.1:34609
I0917 23:14:40.292358 31526 sched.cpp:476] Sending registration request to 
master@127.0.1.1:34609
I0917 23:14:40.292563 31525 master.cpp:1330] Received registration request from 
scheduler-4c79cf12-ea1b-49e5-bae1-d34f91605227@127.0.1.1:34609
I0917 23:14:40.292762 31525 master.cpp:1290] Authorizing framework principal 
'test-principal' to receive offers for role '*'
I0917 23:14:40.293253 31525 master.cpp:1389] Registering framework 
20140917-231435-16842879-34609-31503-0000 at 
scheduler-4c79cf12-ea1b-49e5-bae1-d34f91605227@127.0.1.1:34609
I0917 23:14:40.293767 31525 hierarchical_allocator_process.hpp:329] Added 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.294075 31525 hierarchical_allocator_process.hpp:734] Offering 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.294450 31525 hierarchical_allocator_process.hpp:734] Offering 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.294659 31525 hierarchical_allocator_process.hpp:734] Offering 
cpus(*):1; mem(*):1001; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.295035 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-0 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:40.295318 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-1 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:40.295614 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-2 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:40.295778 31520 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.295984 31525 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 1.975722ms
I0917 23:14:40.296185 31526 sched.cpp:407] Framework registered with 
20140917-231435-16842879-34609-31503-0000
Registered! ID = 20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.317849 31526 sched.cpp:421] Scheduler::registered took 
21.576128ms
Launching task 0
Launching task 1
Launching task 2
I0917 23:14:40.365347 31526 sched.cpp:544] Scheduler::resourceOffers took 
47.086567ms
I0917 23:14:40.365958 31523 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-0 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:40.366112 31523 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-0 ] on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
W0917 23:14:40.366549 31523 master.cpp:1898] Executor default for task 0 uses 
less CPUs (None) than the minimum required (0.01). Please update your executor, 
as this will be mandatory in future releases.
W0917 23:14:40.366693 31523 master.cpp:1909] Executor default for task 0 uses 
less memory (None) than the minimum required (32MB). Please update your 
executor, as this will be mandatory in future releases.
I0917 23:14:40.366950 31523 master.cpp:2311] Authorizing framework principal 
'test-principal' to launch task 0 as user 'jenkins'
I0917 23:14:40.367545 31523 master.hpp:839] Adding task 0 with resources 
cpus(*):1; mem(*):128 on slave 20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:40.367696 31523 master.cpp:2377] Launching task 0 of framework 
20140917-231435-16842879-34609-31503-0000 with resources cpus(*):1; mem(*):128 
on slave 20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 
(saucy)
I0917 23:14:40.367955 31524 slave.cpp:1025] Got assigned task 0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.368505 31524 slave.cpp:1135] Launching task 0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.370308 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.370450 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-0 for 1secs
I0917 23:14:40.371031 31520 containerizer.cpp:394] Starting container 
'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of framework 
'20140917-231435-16842879-34609-31503-0000'
I0917 23:14:40.373828 31524 slave.cpp:1248] Queuing task '0' for executor 
default of framework '20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.374595 31524 slave.cpp:554] Successfully attached file 
'/tmp/mesos-w8snRW/2/slaves/20140917-231435-16842879-34609-31503-0/frameworks/20140917-231435-16842879-34609-31503-0000/executors/default/runs/a70a0cfd-ee78-43a0-b0b7-26bcd205f142'
I0917 23:14:40.374486 31520 launcher.cpp:137] Forked child with pid '31534' for 
container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142'
I0917 23:14:40.375830 31520 containerizer.cpp:510] Fetching URIs for container 
'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' using command 
'/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src/mesos-fetcher'
I0917 23:14:40.377596 31523 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-1 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:40.377781 31523 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-1 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
W0917 23:14:40.378062 31523 master.cpp:1898] Executor default for task 1 uses 
less CPUs (None) than the minimum required (0.01). Please update your executor, 
as this will be mandatory in future releases.
W0917 23:14:40.378233 31523 master.cpp:1909] Executor default for task 1 uses 
less memory (None) than the minimum required (32MB). Please update your 
executor, as this will be mandatory in future releases.
I0917 23:14:40.378429 31523 master.cpp:2311] Authorizing framework principal 
'test-principal' to launch task 1 as user 'jenkins'
I0917 23:14:40.379017 31523 master.hpp:839] Adding task 1 with resources 
cpus(*):1; mem(*):128 on slave 20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:40.379166 31523 master.cpp:2377] Launching task 1 of framework 
20140917-231435-16842879-34609-31503-0000 with resources cpus(*):1; mem(*):128 
on slave 20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 
(saucy)
I0917 23:14:40.379525 31525 slave.cpp:1025] Got assigned task 1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.379914 31525 slave.cpp:1135] Launching task 1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.381691 31519 containerizer.cpp:394] Starting container 
'1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of framework 
'20140917-231435-16842879-34609-31503-0000'
I0917 23:14:40.383585 31525 slave.cpp:1248] Queuing task '1' for executor 
default of framework '20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.384318 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.384598 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs
I0917 23:14:40.384814 31525 slave.cpp:554] Successfully attached file 
'/tmp/mesos-w8snRW/1/slaves/20140917-231435-16842879-34609-31503-2/frameworks/20140917-231435-16842879-34609-31503-0000/executors/default/runs/1c6cf8b1-972b-4b73-8467-bc4503dd9332'
I0917 23:14:40.385326 31526 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-2 with resources cpus(*):1; mem(*):1001; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:40.385509 31526 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-2 ] on slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
W0917 23:14:40.385666 31526 master.cpp:1898] Executor default for task 2 uses 
less CPUs (None) than the minimum required (0.01). Please update your executor, 
as this will be mandatory in future releases.
W0917 23:14:40.385856 31526 master.cpp:1909] Executor default for task 2 uses 
less memory (None) than the minimum required (32MB). Please update your 
executor, as this will be mandatory in future releases.
I0917 23:14:40.386008 31526 master.cpp:2311] Authorizing framework principal 
'test-principal' to launch task 2 as user 'jenkins'
I0917 23:14:40.386518 31526 master.hpp:839] Adding task 2 with resources 
cpus(*):1; mem(*):128 on slave 20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:40.386818 31519 launcher.cpp:137] Forked child with pid '31536' for 
container '1c6cf8b1-972b-4b73-8467-bc4503dd9332'
I0917 23:14:40.393805 31519 containerizer.cpp:510] Fetching URIs for container 
'1c6cf8b1-972b-4b73-8467-bc4503dd9332' using command 
'/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src/mesos-fetcher'
I0917 23:14:40.395980 31526 master.cpp:2377] Launching task 2 of framework 
20140917-231435-16842879-34609-31503-0000 with resources cpus(*):1; mem(*):128 
on slave 20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 
(saucy)
I0917 23:14:40.396574 31521 slave.cpp:1025] Got assigned task 2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.396946 31521 slave.cpp:1135] Launching task 2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.398582 31521 slave.cpp:1248] Queuing task '2' for executor 
default of framework '20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.400519 31521 slave.cpp:554] Successfully attached file 
'/tmp/mesos-w8snRW/0/slaves/20140917-231435-16842879-34609-31503-1/frameworks/20140917-231435-16842879-34609-31503-0000/executors/default/runs/6add4792-3bc4-4ac9-8225-969f09279561'
I0917 23:14:40.400287 31525 containerizer.cpp:394] Starting container 
'6add4792-3bc4-4ac9-8225-969f09279561' for executor 'default' of framework 
'20140917-231435-16842879-34609-31503-0000'
I0917 23:14:40.401595 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:40.403118 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-1 for 1secs
I0917 23:14:40.431401 31525 launcher.cpp:137] Forked child with pid '31551' for 
container '6add4792-3bc4-4ac9-8225-969f09279561'
I0917 23:14:40.436882 31525 containerizer.cpp:510] Fetching URIs for container 
'6add4792-3bc4-4ac9-8225-969f09279561' using command 
'/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src/mesos-fetcher'
I0917 23:14:41.248602 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:41.249043 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:41.249259 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:41.249377 31523 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 1.040603ms
I0917 23:14:41.384321 31526 slave.cpp:2560] Monitoring executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000' in container 
'a70a0cfd-ee78-43a0-b0b7-26bcd205f142'
I0917 23:14:41.395431 31526 slave.cpp:2560] Monitoring executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000' in container 
'1c6cf8b1-972b-4b73-8467-bc4503dd9332'
I0917 23:14:41.413548 31522 slave.cpp:2560] Monitoring executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000' in container 
'6add4792-3bc4-4ac9-8225-969f09279561'
WARNING: Logging before InitGoogleLogging() is written to STDERR
WARNING: Logging before InitGoogleLogging() is written to STDERR
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0917 23:14:41.935613 31641 process.cpp:1771] libprocess is initialized on 
127.0.1.1:40557 for 8 cpus
I0917 23:14:41.938254 31641 logging.cpp:177] Logging to STDERR
I0917 23:14:41.934036 31643 process.cpp:1771] libprocess is initialized on 
127.0.1.1:33558 for 8 cpus
I0917 23:14:41.939977 31643 logging.cpp:177] Logging to STDERR
I0917 23:14:41.937566 31644 process.cpp:1771] libprocess is initialized on 
127.0.1.1:51898 for 8 cpus
II0917 23:14:41.941807 31644 logging.cpp:177] Logging to STDERR
II0917 23:14:41.943460 31641 exec.cpp:132] Version: 0.21.0
0917 23:14:41.941642 31643 exec.cpp:132] Version: 0.21.0
0917 23:14:41.943018 31644 exec.cpp:132] Version: 0.21.0
II0917 23:14:41.950268 31683 exec.cpp:182] Executor started at: 
executor(1)@127.0.1.1:40557 with pid 31636
II0917 23:14:41.951695 31522 slave.cpp:1758] Got registration for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:40557
I0917 23:14:41.952024 31522 slave.cpp:1877] Flushing queued task 0 for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:41.951012 31674 exec.cpp:182] Executor started at: 
executor(1)@127.0.1.1:33558 with pid 31639
I0917 23:14:41.954056 31526 slave.cpp:1758] Got registration for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:33558
I0917 23:14:41.954582 31526 slave.cpp:1877] Flushing queued task 1 for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:41.950121 31692 exec.cpp:182] Executor started at: 
executor(1)@127.0.1.1:51898 with pid 31642
I0917 23:14:41.955857 31521 slave.cpp:1758] Got registration for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:51898
I0917 23:14:41.957639 31521 slave.cpp:1877] Flushing queued task 2 for executor 
'default' of framework 20140917-231435-16842879-34609-31503-0000
0917 23:14:41.955232 31676 exec.cpp:206] Executor registered on slave 
20140917-231435-16842879-34609-31503-2
0917 23:14:41.953346 31685 exec.cpp:206] Executor registered on slave 
20140917-231435-16842879-34609-31503-0
I0917 23:14:41.968797 31694 exec.cpp:206] Executor registered on slave 
20140917-231435-16842879-34609-31503-1
Registered executor on saucyRegistered executor on saucyRegistered executor on 
saucy

II
I0917 23:14:42.169991 31694 exec.cpp:218] Executor::registered took 199.821555ms
I0917 23:14:42.170224 31676 exec.cpp:218] Executor::registered took 208.770192ms
I0917 23:14:42.170574 31685 exec.cpp:218] Executor::registered took 205.42106ms
I0917 23:14:42.171221 31676 exec.cpp:293] Executor asked to run task '1'
0917 23:14:42.170928 31694 exec.cpp:293] Executor asked to run task '2'
0917 23:14:42.171532 31685 exec.cpp:293] Executor asked to run task '0'
III0917 23:14:42.194025 31685 exec.cpp:302] Executor::launchTask took 
20.907244ms
0917 23:14:42.194463 31694 exec.cpp:302] Executor::launchTask took 22.463085ms
0917 23:14:42.193789 31676 exec.cpp:302] Executor::launchTask took 22.090512ms
I0917 23:14:42.249930 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.250046 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.250120 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):873; disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.250221 31520 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 427470ns
I0917 23:14:42.250301 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-3 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:42.250375 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-4 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:42.250427 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-5 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:42.250454 31520 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
Launching task 3
Launching task 4
I0917 23:14:42.256711 31520 sched.cpp:544] Scheduler::resourceOffers took 
6.128709ms
I0917 23:14:42.257067 31519 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-3 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:42.259182 31519 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-3 ] on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
II0917 23:14:42.263245 31519 master.cpp:3234] Sending status update TASK_LOST 
(UUID: 6c082b40-ec70-4c8a-a1b8-5580374e3340) for task 3 of framework 
20140917-231435-16842879-34609-31503-0000 'Task 3 attempted to use cpus(*):1; 
mem(*):128 which is greater than offered mem(*):873; disk(*):24988; 
ports(*):[31000-32000]'
I0917 23:14:42.263723 31523 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.264802 31523 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-0 for 1secs
I0917 23:14:42.265305 31522 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-4 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
II0917 23:14:42.266269 31522 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-4 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.266079 31689 exec.cpp:525] Executor sending status update 
TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000
0917 23:14:42.267781 31672 exec.cpp:525] Executor sending status update 
TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
0917 23:14:42.262806 31678 exec.cpp:525] Executor sending status update 
TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.276619 31521 slave.cpp:2111] Handling status update TASK_RUNNING 
(UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000 from executor(1)@127.0.1.1:33558
I0917 23:14:42.277762 31521 status_update_manager.cpp:320] Received status 
update TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.277570 31525 slave.cpp:2111] Handling status update TASK_RUNNING 
(UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000 from executor(1)@127.0.1.1:40557
I0917 23:14:42.277437 31526 slave.cpp:2111] Handling status update TASK_RUNNING 
(UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000 from executor(1)@127.0.1.1:51898
I0917 23:14:42.280566 31526 status_update_manager.cpp:320] Received status 
update TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.280719 31526 status_update_manager.cpp:499] Creating 
StatusUpdate stream for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.280987 31526 status_update_manager.cpp:373] Forwarding status 
update TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.281231 31526 slave.cpp:2268] Status update manager successfully 
handled status update TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) 
for task 2 of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.281352 31526 slave.cpp:2274] Sending acknowledgement for status 
update TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:51898
I0917 23:14:42.280252 31525 status_update_manager.cpp:320] Received status 
update TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.281714 31525 status_update_manager.cpp:499] Creating 
StatusUpdate stream for task 0 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.281883 31525 status_update_manager.cpp:373] Forwarding status 
update TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.282068 31525 slave.cpp:2268] Status update manager successfully 
handled status update TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) 
for task 0 of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.282349 31525 slave.cpp:2274] Sending acknowledgement for status 
update TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:40557
I0917 23:14:42.282624 31521 status_update_manager.cpp:499] Creating 
StatusUpdate stream for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.282802 31521 status_update_manager.cpp:373] Forwarding status 
update TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.282940 31522 master.cpp:3234] Sending status update TASK_LOST 
(UUID: 24d8174b-ab65-47d0-8e4b-9ad1b5c05030) for task 4 of framework 
20140917-231435-16842879-34609-31503-0000 'Task 4 attempted to use cpus(*):1; 
mem(*):128 which is greater than offered mem(*):873; disk(*):24988; 
ports(*):[31000-32000]'
I0917 23:14:42.283248 31524 slave.cpp:2268] Status update manager successfully 
handled status update TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) 
for task 1 of framework 20140917-231435-16842879-34609-31503-0000
II0917 23:14:42.283634 31524 slave.cpp:2274] Sending acknowledgement for status 
update TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:33558
I0917 23:14:42.284031 31522 master.cpp:3239] Forwarding status update 
TASK_RUNNING (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000
0917 23:14:42.283514 31684 exec.cpp:339] Executor received status update 
acknowledgement 774aa76c-87bd-4d39-a5e2-d880206fedb3 for task 0 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.285044 31522 master.cpp:3205] Status update TASK_RUNNING (UUID: 
d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
I0917 23:14:42.284976 31525 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.285399 31525 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs
I0917 23:14:42.285539 31522 master.cpp:3239] Forwarding status update 
TASK_RUNNING (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.286206 31522 master.cpp:3205] Status update TASK_RUNNING (UUID: 
774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
I0917 23:14:42.286468 31522 master.cpp:3239] Forwarding status update 
TASK_RUNNING (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.286607 31522 master.cpp:3205] Status update TASK_RUNNING (UUID: 
3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:42.286854 31524 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-5 with resources mem(*):873; 
disk(*):24988; ports(*):[31000-32000] on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
II0917 23:14:42.287259 31524 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-5 ] on slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
0917 23:14:42.287132 31671 exec.cpp:339] Executor received status update 
acknowledgement 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.287842 31524 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):873; disk(*):24988; ports(*):[31000-32000] (total allocatable: 
mem(*):873; disk(*):24988; ports(*):[31000-32000]) on slave 
20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
II0917 23:14:42.291944 31524 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-1 for 1secs
0917 23:14:42.288897 31688 exec.cpp:339] Executor received status update 
acknowledgement d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
Status update: task 3 is in state TASK_LOST
I0917 23:14:42.314281 31520 sched.cpp:635] Scheduler::statusUpdate took 
21.943967ms
Status update: task 4 is in state TASK_LOST
I0917 23:14:42.314991 31520 sched.cpp:635] Scheduler::statusUpdate took 513983ns
Status update: task 2 is in state TASK_RUNNING
I0917 23:14:42.316504 31520 sched.cpp:635] Scheduler::statusUpdate took 
1.370298ms
I0917 23:14:42.316826 31526 master.cpp:2720] Forwarding status update 
acknowledgement d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad for task 2 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
I0917 23:14:42.318004 31526 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.318320 31526 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
d4ac4252-ea9d-4c1d-b8c9-ea2d9704e6ad) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
Status update: task 0 is in state TASK_RUNNING
I0917 23:14:42.319246 31520 sched.cpp:635] Scheduler::statusUpdate took 546461ns
I0917 23:14:42.319432 31521 master.cpp:2720] Forwarding status update 
acknowledgement 774aa76c-87bd-4d39-a5e2-d880206fedb3 for task 0 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
I0917 23:14:42.319612 31521 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: 774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.319789 31521 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
774aa76c-87bd-4d39-a5e2-d880206fedb3) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000
Status update: task 1 is in state TASK_RUNNING
I0917 23:14:42.325856 31520 sched.cpp:635] Scheduler::statusUpdate took 
5.910398ms
I0917 23:14:42.326161 31519 master.cpp:2720] Forwarding status update 
acknowledgement 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb for task 1 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:42.326392 31522 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: 3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.326689 31522 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
3a405ad5-f8f8-4a7d-9f3d-ba0d02ab4cdb) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.385427 31524 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:42.396478 31524 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
Running task value: "1"
Running task value: "0"

Running task value: "2"


I0917 23:14:42.747750 31669 exec.cpp:525] Executor sending status update 
TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.748468 31525 slave.cpp:2111] Handling status update 
TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:33558
I0917 23:14:42.748540 31525 slave.cpp:3938] Terminating task 1
I0917 23:14:42.748910 31525 status_update_manager.cpp:320] Received status 
update TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.748955 31525 status_update_manager.cpp:373] Forwarding status 
update TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.749049 31525 master.cpp:3239] Forwarding status update 
TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.749084 31525 master.cpp:3205] Status update TASK_FINISHED (UUID: 
c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:42.749125 31525 master.cpp:4385] Removing task 1 with resources 
cpus(*):1; mem(*):128 of framework 20140917-231435-16842879-34609-31503-0000 on 
slave 20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:42.749271 31525 slave.cpp:2268] Status update manager successfully 
handled status update TASK_FINISHED (UUID: 
c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.749285 31525 slave.cpp:2274] Sending acknowledgement for status 
update TASK_FINISHED (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:33558
I0917 23:14:42.749987 31521 hierarchical_allocator_process.hpp:563] Recovered 
cpus(*):1; mem(*):128 (total allocatable: mem(*):1001; disk(*):24988; 
ports(*):[31000-32000]; cpus(*):1) on slave 
20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
Status update: task 1 is in state TASK_FINISHED
Finished tasks: 1
I0917 23:14:42.751500 31525 sched.cpp:635] Scheduler::statusUpdate took 
2.067671ms
I0917 23:14:42.751701 31521 master.cpp:2720] Forwarding status update 
acknowledgement c3e603da-200e-4ac6-8ec4-ab09bd839be7 for task 1 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy)
I0917 23:14:42.751891 31521 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.752101 31521 status_update_manager.cpp:530] Cleaning up status 
update stream for task 1 of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.752358 31521 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
c3e603da-200e-4ac6-8ec4-ab09bd839be7) for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.752497 31521 slave.cpp:3977] Completing task 1
III0917 23:14:42.753000 31669 exec.cpp:339] Executor received status update 
acknowledgement c3e603da-200e-4ac6-8ec4-ab09bd839be7 for task 1 of framework 
20140917-231435-16842879-34609-31503-0000
0917 23:14:42.753515 31680 exec.cpp:525] Executor sending status update 
TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.755370 31519 slave.cpp:2111] Handling status update 
TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:40557
I0917 23:14:42.755519 31519 slave.cpp:3938] Terminating task 0
I0917 23:14:42.755897 31519 status_update_manager.cpp:320] Received status 
update TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.756033 31519 status_update_manager.cpp:373] Forwarding status 
update TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.756324 31519 master.cpp:3239] Forwarding status update 
TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.756497 31519 master.cpp:3205] Status update TASK_FINISHED (UUID: 
7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
0917 23:14:42.754186 31693 exec.cpp:525] Executor sending status update 
TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000
Status update: task 0 is in state TASK_FINISHEDI0917 23:14:42.764149 31519 
master.cpp:4385] Removing task 0 with resources cpus(*):1; mem(*):128 of 
framework 20140917-231435-16842879-34609-31503-0000 on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
I0917 23:14:42.756443 31523 slave.cpp:2268] Status update manager successfully 
handled status update TASK_FINISHED (UUID: 
7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.766275 31523 slave.cpp:2274] Sending acknowledgement for status 
update TASK_FINISHED (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:40557
I0917 23:14:42.766705 31523 hierarchical_allocator_process.hpp:563] Recovered 
cpus(*):1; mem(*):128 (total allocatable: mem(*):1001; disk(*):24988; 
ports(*):[31000-32000]; cpus(*):1) on slave 
20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.767081 31519 slave.cpp:2111] Handling status update 
TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000 from 
executor(1)@127.0.1.1:51898
I0917 23:14:42.767195 31519 slave.cpp:3938] Terminating task 2
I0917 23:14:42.767546 31519 status_update_manager.cpp:320] Received status 
update TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000

Finished tasks: 2
I0917 23:14:42.768301 31519 status_update_manager.cpp:373] Forwarding status 
update TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000 to master@127.0.1.1:34609
I0917 23:14:42.768503 31519 master.cpp:3239] Forwarding status update 
TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.768614 31523 slave.cpp:2268] Status update manager successfully 
handled status update TASK_FINISHED (UUID: 
de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.768723 31523 slave.cpp:2274] Sending acknowledgement for status 
update TASK_FINISHED (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of 
framework 20140917-231435-16842879-34609-31503-0000 to 
executor(1)@127.0.1.1:51898
I0917 23:14:42.768264 31521 sched.cpp:635] Scheduler::statusUpdate took 
7.95946ms
I0917 23:14:42.769163 31519 master.cpp:3205] Status update TASK_FINISHED (UUID: 
de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000 from slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
Status update: task 2 is in state TASK_FINISHEDII0917 23:14:42.769947 31691 
exec.cpp:339] Executor received status update acknowledgement 
de91c600-abe2-4081-ad39-25fbd637b938 for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
0917 23:14:42.770182 31682 exec.cpp:339] Executor received status update 
acknowledgement 7870de4c-5721-4dbb-b50c-0077513d6e78 for task 0 of framework 
20140917-231435-16842879-34609-31503-0000

Finished tasks: 3
I0917 23:14:42.776676 31519 master.cpp:4385] Removing task 2 with resources 
cpus(*):1; mem(*):128 of framework 20140917-231435-16842879-34609-31503-0000 on 
slave 20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
I0917 23:14:42.776577 31523 sched.cpp:635] Scheduler::statusUpdate took 
7.246343ms
I0917 23:14:42.777061 31519 master.cpp:2720] Forwarding status update 
acknowledgement 7870de4c-5721-4dbb-b50c-0077513d6e78 for task 0 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy)
I0917 23:14:42.777197 31523 hierarchical_allocator_process.hpp:563] Recovered 
cpus(*):1; mem(*):128 (total allocatable: mem(*):1001; disk(*):24988; 
ports(*):[31000-32000]; cpus(*):1) on slave 
20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.777384 31519 master.cpp:2720] Forwarding status update 
acknowledgement de91c600-abe2-4081-ad39-25fbd637b938 for task 2 of framework 
20140917-231435-16842879-34609-31503-0000 to slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy)
I0917 23:14:42.777580 31519 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: de91c600-abe2-4081-ad39-25fbd637b938) for task 2 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.777721 31519 status_update_manager.cpp:530] Cleaning up status 
update stream for task 2 of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.777523 31523 status_update_manager.cpp:398] Received status 
update acknowledgement (UUID: 7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 
of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.777992 31523 status_update_manager.cpp:530] Cleaning up status 
update stream for task 0 of framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.778156 31519 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
de91c600-abe2-4081-ad39-25fbd637b938) for task 2 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.778313 31519 slave.cpp:3977] Completing task 2
I0917 23:14:42.778291 31521 slave.cpp:1698] Status update manager successfully 
handled status update acknowledgement (UUID: 
7870de4c-5721-4dbb-b50c-0077513d6e78) for task 0 of framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:42.779542 31521 slave.cpp:3977] Completing task 0
I0917 23:14:43.250752 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.251107 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.251287 31520 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.251521 31520 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 867376ns
I0917 23:14:43.251665 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-6 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:43.251854 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-7 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:43.252030 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-8 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:43.252184 31523 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.253651 31523 sched.cpp:544] Scheduler::resourceOffers took 
1.199343ms
I0917 23:14:43.254057 31524 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-6 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:43.254179 31524 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-6 ] on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.254555 31524 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.254693 31524 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-0 for 1secs
I0917 23:14:43.254902 31521 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-7 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:43.255035 31521 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-7 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.255257 31521 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.255414 31521 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs
I0917 23:14:43.255630 31522 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-8 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:43.255754 31522 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-8 ] on slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.255944 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:43.256085 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-1 for 1secs
I0917 23:14:43.386253 31522 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:43.397584 31521 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:44.252192 31525 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:44.252557 31525 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:44.252712 31525 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:44.252879 31525 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 791479ns
I0917 23:14:44.386862 31523 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:44.398048 31524 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:45.247548 31520 master.cpp:120] No whitelist given. Advertising 
offers for all slaves
I0917 23:14:45.253939 31521 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.254165 31521 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.254356 31521 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.254585 31521 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 762921ns
I0917 23:14:45.254741 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-9 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:45.254945 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-10 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:45.255112 31523 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-11 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:45.255259 31523 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.256947 31523 sched.cpp:544] Scheduler::resourceOffers took 
1.430971ms
I0917 23:14:45.257366 31524 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-9 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:45.257498 31524 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-9 ] on slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.257766 31524 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.257901 31524 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-1 for 1secs
I0917 23:14:45.258277 31522 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-10 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:45.258407 31522 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-10 ] on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.258625 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.258771 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-0 for 1secs
I0917 23:14:45.258975 31522 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-11 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:45.259114 31522 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-11 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.259313 31522 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:45.259464 31522 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs
I0917 23:14:45.388000 31524 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:45.399271 31521 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:46.254964 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:46.255506 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:46.255667 31523 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:46.255867 31523 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 1.022627ms
I0917 23:14:46.388937 31525 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:46.400216 31520 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:47.256769 31523 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.257114 31523 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.257302 31523 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.257544 31523 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 848269ns
I0917 23:14:47.257709 31521 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-12 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:47.257920 31521 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-13 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:47.258103 31521 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-14 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:47.258236 31521 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.260226 31521 sched.cpp:544] Scheduler::resourceOffers took 
1.743624ms
I0917 23:14:47.260470 31525 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-12 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:47.260594 31525 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-12 ] on slave 
20140917-231435-16842879-34609-31503-0 at slave(3)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.260891 31525 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-0 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.261092 31525 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-0 for 1secs
I0917 23:14:47.261380 31519 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-13 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:47.261514 31519 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-13 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.261744 31519 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.261873 31519 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs
I0917 23:14:47.262086 31520 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-14 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:47.262212 31520 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-14 ] on slave 
20140917-231435-16842879-34609-31503-1 at slave(1)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.262408 31520 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-1 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:47.262526 31520 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-1 for 1secs
I0917 23:14:47.390128 31520 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:47.401535 31520 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:48.258159 31520 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:48.258453 31520 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:48.258616 31520 hierarchical_allocator_process.hpp:816] Filtered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 for framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:48.258735 31520 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 726125ns
I0917 23:14:48.390913 31519 monitor.cpp:140] Failed to collect resource usage 
for container 'a70a0cfd-ee78-43a0-b0b7-26bcd205f142' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
a70a0cfd-ee78-43a0-b0b7-26bcd205f142
I0917 23:14:48.402195 31523 monitor.cpp:140] Failed to collect resource usage 
for container '1c6cf8b1-972b-4b73-8467-bc4503dd9332' for executor 'default' of 
framework '20140917-231435-16842879-34609-31503-0000': Unknown container: 
1c6cf8b1-972b-4b73-8467-bc4503dd9332
I0917 23:14:49.260015 31519 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.260422 31519 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.260701 31519 hierarchical_allocator_process.hpp:734] Offering 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.260953 31519 hierarchical_allocator_process.hpp:659] Performed 
allocation for 3 slaves in 1.015379ms
I0917 23:14:49.261144 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-15 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:49.261371 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-16 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-0 (saucy)
I0917 23:14:49.261576 31520 master.hpp:862] Adding offer 
20140917-231435-16842879-34609-31503-17 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-1 (saucy)
I0917 23:14:49.261729 31520 master.cpp:3616] Sending 3 offers to framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.263228 31520 sched.cpp:544] Scheduler::resourceOffers took 
1.214892ms
I0917 23:14:49.263566 31524 master.hpp:871] Removing offer 
20140917-231435-16842879-34609-31503-15 with resources mem(*):1001; 
disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 
20140917-231435-16842879-34609-31503-2 (saucy)
I0917 23:14:49.263701 31524 master.cpp:2228] Processing reply for offers: [ 
20140917-231435-16842879-34609-31503-15 ] on slave 
20140917-231435-16842879-34609-31503-2 at slave(2)@127.0.1.1:34609 (saucy) for 
framework 20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.264742 31524 hierarchical_allocator_process.hpp:563] Recovered 
mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total 
allocatable: mem(*):1001; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on 
slave 20140917-231435-16842879-34609-31503-2 from framework 
20140917-231435-16842879-34609-31503-0000
I0917 23:14:49.264775 31524 hierarchical_allocator_process.hpp:599] Framework 
20140917-231435-16842879-34609-31503-0000 filtered slave 
20140917-231435-16842879-34609-31503-2 for 1secs

{code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Reply via email to