You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/09/19 01:13:34 UTC
[jira] [Commented] (MESOS-1814) Task attempted to use more offers
than requested in example jave and python frameworks
[ https://issues.apache.org/jira/browse/MESOS-1814?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14139686#comment-14139686 ]
Vinod Kone commented on MESOS-1814:
-----------------------------------
https://reviews.apache.org/r/25801/
> Task attempted to use more offers than requested in example jave and python frameworks
> --------------------------------------------------------------------------------------
>
> Key: MESOS-1814
> URL: https://issues.apache.org/jira/browse/MESOS-1814
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.21.0
> Reporter: Vinod Kone
> Assignee: 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)