You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Cody Maloney (JIRA)" <ji...@apache.org> on 2014/12/04 22:28:14 UTC
[jira] [Updated] (MESOS-1785)
ExampleTest.LowLevelSchedulerLibprocess is flaky
[ https://issues.apache.org/jira/browse/MESOS-1785?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Cody Maloney updated MESOS-1785:
--------------------------------
Labels: flaky (was: )
> ExampleTest.LowLevelSchedulerLibprocess is flaky
> ------------------------------------------------
>
> Key: MESOS-1785
> URL: https://issues.apache.org/jira/browse/MESOS-1785
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.20.0
> Reporter: Yan Xu
> Labels: flaky
>
> The test lasted forever because task 1 is not completed.
> {noformat:title=log}
> [ RUN ] ExamplesTest.LowLevelSchedulerLibprocess
> Using temporary directory '/tmp/ExamplesTest_LowLevelSchedulerLibprocess_s2iS1n'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0910 05:57:28.191807 17625 process.cpp:1771] libprocess is initialized on 127.0.1.1:47878 for 8 cpus
> Enabling authentication for the scheduler
> I0910 05:57:28.193083 17625 logging.cpp:177] Logging to STDERR
> I0910 05:57:28.193274 17625 scheduler.cpp:145] Version: 0.21.0
> I0910 05:57:28.224969 17625 leveldb.cpp:176] Opened db in 29.007559ms
> I0910 05:57:28.234238 17625 leveldb.cpp:183] Compacted db in 9.042296ms
> I0910 05:57:28.234468 17625 leveldb.cpp:198] Created db iterator in 32144ns
> I0910 05:57:28.234742 17625 leveldb.cpp:204] Seeked to beginning of db in 1548ns
> I0910 05:57:28.234879 17625 leveldb.cpp:273] Iterated through 0 keys in the db in 5502ns
> I0910 05:57:28.235086 17625 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0910 05:57:28.237017 17654 master.cpp:286] Master 20140910-055728-16842879-47878-17625 (trusty) started on 127.0.1.1:47878
> I0910 05:57:28.237479 17654 master.cpp:332] Master only allowing authenticated frameworks to register
> I0910 05:57:28.237592 17654 master.cpp:339] Master allowing unauthenticated slaves to register
> I0910 05:57:28.237733 17654 credentials.hpp:36] Loading credentials for authentication from '/tmp/ExamplesTest_LowLevelSchedulerLibprocess_s2iS1n/credentials'
> W0910 05:57:28.237985 17654 credentials.hpp:51] Permissions on credentials file '/tmp/ExamplesTest_LowLevelSchedulerLibprocess_s2iS1n/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
> I0910 05:57:28.238147 17654 master.cpp:366] Authorization enabled
> I0910 05:57:28.237361 17652 recover.cpp:425] Starting replica recovery
> I0910 05:57:28.238878 17651 recover.cpp:451] Replica is in EMPTY status
> I0910 05:57:28.239704 17651 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0910 05:57:28.240255 17651 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0910 05:57:28.240582 17651 recover.cpp:542] Updating replica status to STARTING
> I0910 05:57:28.240134 17650 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0910 05:57:28.241950 17652 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@127.0.1.1:47878
> I0910 05:57:28.243247 17651 master.cpp:1212] The newly elected leader is master@127.0.1.1:47878 with id 20140910-055728-16842879-47878-17625
> I0910 05:57:28.243402 17651 master.cpp:1225] Elected as the leading master!
> I0910 05:57:28.243620 17651 master.cpp:1043] Recovering from registrar
> I0910 05:57:28.243831 17651 registrar.cpp:313] Recovering registrar
> I0910 05:57:28.244851 17625 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0910 05:57:28.246381 17652 slave.cpp:167] Slave started on 1)@127.0.1.1:47878
> I0910 05:57:28.246824 17652 slave.cpp:287] Slave resources: cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:28.247046 17652 slave.cpp:315] Slave hostname: trusty
> I0910 05:57:28.247133 17652 slave.cpp:316] Slave checkpoint: true
> I0910 05:57:28.247632 17652 state.cpp:33] Recovering state from '/tmp/mesos-SUO0qf/0/meta'
> I0910 05:57:28.247834 17650 status_update_manager.cpp:193] Recovering status update manager
> I0910 05:57:28.247987 17650 containerizer.cpp:252] Recovering containerizer
> I0910 05:57:28.248399 17652 slave.cpp:3202] Finished recovery
> I0910 05:57:28.248921 17652 slave.cpp:598] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.249073 17656 status_update_manager.cpp:167] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.249191 17652 slave.cpp:634] No credentials provided. Attempting to register without authentication
> I0910 05:57:28.249337 17652 slave.cpp:645] Detecting new master
> I0910 05:57:28.249740 17625 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0910 05:57:28.251518 17650 slave.cpp:167] Slave started on 2)@127.0.1.1:47878
> I0910 05:57:28.251782 17650 slave.cpp:287] Slave resources: cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:28.251960 17650 slave.cpp:315] Slave hostname: trusty
> I0910 05:57:28.252079 17650 slave.cpp:316] Slave checkpoint: true
> I0910 05:57:28.252481 17650 state.cpp:33] Recovering state from '/tmp/mesos-SUO0qf/1/meta'
> I0910 05:57:28.252691 17650 status_update_manager.cpp:193] Recovering status update manager
> I0910 05:57:28.252831 17650 containerizer.cpp:252] Recovering containerizer
> I0910 05:57:28.253132 17650 slave.cpp:3202] Finished recovery
> I0910 05:57:28.253579 17650 slave.cpp:598] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.253731 17656 status_update_manager.cpp:167] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.253898 17650 slave.cpp:634] No credentials provided. Attempting to register without authentication
> I0910 05:57:28.254050 17650 slave.cpp:645] Detecting new master
> I0910 05:57:28.254454 17625 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0910 05:57:28.255102 17653 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.192475ms
> I0910 05:57:28.255228 17653 replica.cpp:320] Persisted replica status to STARTING
> I0910 05:57:28.255471 17652 recover.cpp:451] Replica is in STARTING status
> I0910 05:57:28.255926 17652 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0910 05:57:28.256093 17652 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0910 05:57:28.256273 17652 recover.cpp:542] Updating replica status to VOTING
> I0910 05:57:28.257381 17655 slave.cpp:167] Slave started on 3)@127.0.1.1:47878
> I0910 05:57:28.257695 17655 slave.cpp:287] Slave resources: cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:28.257930 17655 slave.cpp:315] Slave hostname: trusty
> I0910 05:57:28.258031 17655 slave.cpp:316] Slave checkpoint: true
> I0910 05:57:28.258411 17655 state.cpp:33] Recovering state from '/tmp/mesos-SUO0qf/2/meta'
> I0910 05:57:28.258581 17655 status_update_manager.cpp:193] Recovering status update manager
> I0910 05:57:28.258792 17655 containerizer.cpp:252] Recovering containerizer
> I0910 05:57:28.259192 17655 slave.cpp:3202] Finished recovery
> I0910 05:57:28.259762 17655 slave.cpp:598] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.259917 17655 slave.cpp:634] No credentials provided. Attempting to register without authentication
> I0910 05:57:28.260085 17655 slave.cpp:645] Detecting new master
> I0910 05:57:28.260049 17651 status_update_manager.cpp:167] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.261306 17650 scheduler.cpp:414] New master detected at master@127.0.1.1:47878
> I0910 05:57:28.261423 17650 scheduler.cpp:463] Authenticating with master master@127.0.1.1:47878
> I0910 05:57:28.261716 17650 authenticatee.hpp:104] Initializing client SASL
> I0910 05:57:28.264114 17650 authenticatee.hpp:128] Creating new client SASL connection
> I0910 05:57:28.264613 17651 master.cpp:874] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
> I0910 05:57:28.269175 17652 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.717545ms
> I0910 05:57:28.269318 17652 replica.cpp:320] Persisted replica status to VOTING
> I0910 05:57:28.269624 17652 recover.cpp:556] Successfully joined the Paxos group
> I0910 05:57:28.269872 17652 recover.cpp:440] Recover process terminated
> I0910 05:57:28.270190 17654 log.cpp:656] Attempting to start the writer
> I0910 05:57:28.270813 17654 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0910 05:57:28.283473 17654 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.431777ms
> I0910 05:57:28.283668 17654 replica.cpp:342] Persisted promised to 1
> I0910 05:57:28.284363 17654 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0910 05:57:28.284888 17654 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0910 05:57:28.294821 17654 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 9.665637ms
> I0910 05:57:28.295028 17654 replica.cpp:676] Persisted action at 0
> I0910 05:57:28.298115 17651 replica.cpp:508] Replica received write request for position 0
> I0910 05:57:28.298454 17651 leveldb.cpp:438] Reading position from leveldb took 195540ns
> I0910 05:57:28.311286 17651 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 12.690892ms
> I0910 05:57:28.311476 17651 replica.cpp:676] Persisted action at 0
> I0910 05:57:28.312026 17651 replica.cpp:655] Replica received learned notice for position 0
> I0910 05:57:28.324661 17651 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 12.394907ms
> I0910 05:57:28.324820 17651 replica.cpp:676] Persisted action at 0
> I0910 05:57:28.324970 17651 replica.cpp:661] Replica learned NOP action at position 0
> I0910 05:57:28.325343 17651 log.cpp:672] Writer started with ending position 0
> I0910 05:57:28.325974 17652 leveldb.cpp:438] Reading position from leveldb took 20738ns
> I0910 05:57:28.327158 17656 registrar.cpp:346] Successfully fetched the registry (0B)
> I0910 05:57:28.327304 17656 registrar.cpp:422] Attempting to update the 'registry'
> I0910 05:57:28.328590 17655 log.cpp:680] Attempting to append 119 bytes to the log
> I0910 05:57:28.328797 17655 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0910 05:57:28.329084 17655 replica.cpp:508] Replica received write request for position 1
> I0910 05:57:28.338376 17655 leveldb.cpp:343] Persisting action (136 bytes) to leveldb took 9.147999ms
> I0910 05:57:28.338523 17655 replica.cpp:676] Persisted action at 1
> I0910 05:57:28.338934 17655 replica.cpp:655] Replica received learned notice for position 1
> I0910 05:57:28.348162 17655 leveldb.cpp:343] Persisting action (138 bytes) to leveldb took 9.088091ms
> I0910 05:57:28.348316 17655 replica.cpp:676] Persisted action at 1
> I0910 05:57:28.348429 17655 replica.cpp:661] Replica learned APPEND action at position 1
> I0910 05:57:28.348907 17655 registrar.cpp:479] Successfully updated 'registry'
> I0910 05:57:28.349086 17655 registrar.cpp:372] Successfully recovered registrar
> I0910 05:57:28.349032 17651 log.cpp:699] Attempting to truncate the log to 1
> I0910 05:57:28.349341 17655 master.cpp:1070] Recovered 0 slaves from the Registry (83B) ; allowing 10mins for slaves to re-register
> I0910 05:57:28.349488 17655 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0910 05:57:28.349807 17655 replica.cpp:508] Replica received write request for position 2
> I0910 05:57:28.364025 17655 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 14.076036ms
> I0910 05:57:28.364501 17655 replica.cpp:676] Persisted action at 2
> I0910 05:57:28.364789 17655 replica.cpp:655] Replica received learned notice for position 2
> I0910 05:57:28.374176 17655 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 9.195747ms
> I0910 05:57:28.374372 17655 leveldb.cpp:401] Deleting ~1 keys from leveldb took 40463ns
> I0910 05:57:28.374629 17655 replica.cpp:676] Persisted action at 2
> I0910 05:57:28.374727 17655 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0910 05:57:28.648779 17649 slave.cpp:980] Will retry registration in 445.955946ms if necessary
> I0910 05:57:30.218972 17649 master.cpp:2843] Registering slave at slave(2)@127.0.1.1:47878 (trusty) with id 20140910-055728-16842879-47878-17625-0
> I0910 05:57:30.219151 17649 slave.cpp:980] Will retry registration in 225.822419ms if necessary
> I0910 05:57:30.219207 17649 slave.cpp:980] Will retry registration in 905.362314ms if necessary
> I0910 05:57:30.219244 17649 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0910 05:57:30.219255 17649 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 18746ns
> I0910 05:57:30.219310 17649 registrar.cpp:422] Attempting to update the 'registry'
> I0910 05:57:30.220548 17656 master.cpp:2843] Registering slave at slave(3)@127.0.1.1:47878 (trusty) with id 20140910-055728-16842879-47878-17625-1
> I0910 05:57:30.220646 17656 master.cpp:2843] Registering slave at slave(1)@127.0.1.1:47878 (trusty) with id 20140910-055728-16842879-47878-17625-2
> I0910 05:57:30.221094 17649 log.cpp:680] Attempting to append 292 bytes to the log
> I0910 05:57:30.221155 17649 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0910 05:57:30.221389 17649 replica.cpp:508] Replica received write request for position 3
> I0910 05:57:30.227725 17649 leveldb.cpp:343] Persisting action (311 bytes) to leveldb took 6.298458ms
> I0910 05:57:30.227793 17649 replica.cpp:676] Persisted action at 3
> I0910 05:57:30.228116 17649 replica.cpp:655] Replica received learned notice for position 3
> I0910 05:57:30.233538 17649 leveldb.cpp:343] Persisting action (313 bytes) to leveldb took 5.392308ms
> I0910 05:57:30.233575 17649 replica.cpp:676] Persisted action at 3
> I0910 05:57:30.233585 17649 replica.cpp:661] Replica learned APPEND action at position 3
> I0910 05:57:30.234066 17649 registrar.cpp:479] Successfully updated 'registry'
> I0910 05:57:30.234130 17649 registrar.cpp:422] Attempting to update the 'registry'
> I0910 05:57:30.234972 17655 master.cpp:2883] Registered slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:30.235009 17655 master.cpp:4126] Adding slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:30.235131 17655 log.cpp:699] Attempting to truncate the log to 3
> I0910 05:57:30.235190 17655 slave.cpp:763] Registered with master master@127.0.1.1:47878; given slave ID 20140910-055728-16842879-47878-17625-0
> I0910 05:57:30.235445 17655 slave.cpp:776] Checkpointing SlaveInfo to '/tmp/mesos-SUO0qf/1/meta/slaves/20140910-055728-16842879-47878-17625-0/slave.info'
> I0910 05:57:30.235669 17655 hierarchical_allocator_process.hpp:442] Added slave 20140910-055728-16842879-47878-17625-0 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] available)
> I0910 05:57:30.235749 17655 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140910-055728-16842879-47878-17625-0 in 44889ns
> I0910 05:57:30.235771 17655 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0910 05:57:30.235844 17655 slave.cpp:2329] Received ping from slave-observer(1)@127.0.1.1:47878
> I0910 05:57:30.235966 17655 replica.cpp:508] Replica received write request for position 4
> I0910 05:57:30.241765 17655 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.773496ms
> I0910 05:57:30.241845 17655 replica.cpp:676] Persisted action at 4
> I0910 05:57:30.246214 17651 replica.cpp:655] Replica received learned notice for position 4
> I0910 05:57:30.252013 17651 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.441312ms
> I0910 05:57:30.252203 17651 leveldb.cpp:401] Deleting ~2 keys from leveldb took 34482ns
> I0910 05:57:30.252418 17651 replica.cpp:676] Persisted action at 4
> I0910 05:57:30.252540 17651 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0910 05:57:30.252835 17651 log.cpp:680] Attempting to append 626 bytes to the log
> I0910 05:57:30.253005 17651 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0910 05:57:30.253335 17651 replica.cpp:508] Replica received write request for position 5
> I0910 05:57:30.259165 17651 leveldb.cpp:343] Persisting action (645 bytes) to leveldb took 5.704109ms
> I0910 05:57:30.259351 17651 replica.cpp:676] Persisted action at 5
> I0910 05:57:30.261126 17650 replica.cpp:655] Replica received learned notice for position 5
> I0910 05:57:30.266495 17650 leveldb.cpp:343] Persisting action (647 bytes) to leveldb took 5.252463ms
> I0910 05:57:30.266650 17650 replica.cpp:676] Persisted action at 5
> I0910 05:57:30.266974 17650 replica.cpp:661] Replica learned APPEND action at position 5
> I0910 05:57:30.267518 17650 registrar.cpp:479] Successfully updated 'registry'
> I0910 05:57:30.267822 17650 log.cpp:699] Attempting to truncate the log to 5
> I0910 05:57:30.267966 17650 master.cpp:2883] Registered slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:30.268117 17650 master.cpp:4126] Adding slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:30.268335 17650 master.cpp:2883] Registered slave 20140910-055728-16842879-47878-17625-2 at slave(1)@127.0.1.1:47878 (trusty)
> I0910 05:57:30.268435 17650 master.cpp:4126] Adding slave 20140910-055728-16842879-47878-17625-2 at slave(1)@127.0.1.1:47878 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> I0910 05:57:30.268671 17650 slave.cpp:763] Registered with master master@127.0.1.1:47878; given slave ID 20140910-055728-16842879-47878-17625-1
> I0910 05:57:30.269270 17650 slave.cpp:776] Checkpointing SlaveInfo to '/tmp/mesos-SUO0qf/2/meta/slaves/20140910-055728-16842879-47878-17625-1/slave.info'
> I0910 05:57:30.268874 17656 hierarchical_allocator_process.hpp:442] Added slave 20140910-055728-16842879-47878-17625-1 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] available)
> I0910 05:57:30.269561 17656 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140910-055728-16842879-47878-17625-1 in 17410ns
> I0910 05:57:30.269724 17656 hierarchical_allocator_process.hpp:442] Added slave 20140910-055728-16842879-47878-17625-2 (trusty) with cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] available)
> I0910 05:57:30.269888 17656 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140910-055728-16842879-47878-17625-2 in 7901ns
> I0910 05:57:30.268955 17652 slave.cpp:763] Registered with master master@127.0.1.1:47878; given slave ID 20140910-055728-16842879-47878-17625-2
> I0910 05:57:30.270326 17652 slave.cpp:776] Checkpointing SlaveInfo to '/tmp/mesos-SUO0qf/0/meta/slaves/20140910-055728-16842879-47878-17625-2/slave.info'
> I0910 05:57:30.270746 17652 slave.cpp:2329] Received ping from slave-observer(3)@127.0.1.1:47878
> I0910 05:57:30.268576 17651 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0910 05:57:30.271384 17651 replica.cpp:508] Replica received write request for position 6
> I0910 05:57:30.271831 17650 slave.cpp:2329] Received ping from slave-observer(2)@127.0.1.1:47878
> I0910 05:57:30.277555 17651 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 6.04506ms
> I0910 05:57:30.277695 17651 replica.cpp:676] Persisted action at 6
> I0910 05:57:30.278113 17651 replica.cpp:655] Replica received learned notice for position 6
> I0910 05:57:30.285634 17651 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.341318ms
> I0910 05:57:30.286047 17651 leveldb.cpp:401] Deleting ~2 keys from leveldb took 188970ns
> I0910 05:57:30.286175 17651 replica.cpp:676] Persisted action at 6
> I0910 05:57:30.286278 17651 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0910 05:57:31.219444 17651 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 104933ns
> I0910 05:57:32.220765 17650 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 48485ns
> I0910 05:57:32.769574 17597 exec.cpp:86] Committing suicide by killing the process group
> I0910 05:57:32.770097 17611 exec.cpp:86] Committing suicide by killing the process group
> I0910 05:57:32.774010 17603 exec.cpp:86] Committing suicide by killing the process group
> I0910 05:57:33.221494 17654 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 100988ns
> I0910 05:57:33.241812 17655 master.cpp:120] No whitelist given. Advertising offers for all slaves
> W0910 05:57:33.262215 17656 scheduler.cpp:555] Authentication timed out
> I0910 05:57:33.262758 17656 scheduler.cpp:514] Failed to authenticate with master master@127.0.1.1:47878: Authentication discarded
> I0910 05:57:33.262940 17656 scheduler.cpp:463] Authenticating with master master@127.0.1.1:47878
> I0910 05:57:33.263198 17656 authenticatee.hpp:128] Creating new client SASL connection
> I0910 05:57:33.263723 17656 master.cpp:3653] Authenticating scheduler(1)@127.0.1.1:47878
> I0910 05:57:33.264156 17656 authenticator.hpp:94] Initializing server SASL
> I0910 05:57:33.264747 17656 auxprop.cpp:45] Initialized in-memory auxiliary property plugin
> I0910 05:57:33.264864 17656 authenticator.hpp:156] Creating new server SASL connection
> I0910 05:57:33.265233 17650 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0910 05:57:33.265346 17650 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0910 05:57:33.265552 17656 authenticator.hpp:262] Received SASL authentication start
> I0910 05:57:33.265700 17656 authenticator.hpp:384] Authentication requires more steps
> I0910 05:57:33.265982 17654 authenticatee.hpp:265] Received SASL authentication step
> I0910 05:57:33.266134 17656 authenticator.hpp:290] Received SASL authentication step
> I0910 05:57:33.266242 17656 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0910 05:57:33.266360 17656 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0910 05:57:33.266480 17656 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0910 05:57:33.266609 17656 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0910 05:57:33.266705 17656 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0910 05:57:33.266829 17656 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0910 05:57:33.266970 17656 authenticator.hpp:376] Authentication success
> I0910 05:57:33.267180 17653 authenticatee.hpp:305] Authentication success
> I0910 05:57:33.269915 17653 scheduler.cpp:533] Successfully authenticated with master master@127.0.1.1:47878
> I0910 05:57:33.270133 17652 master.cpp:3693] Successfully authenticated principal 'test-principal' at scheduler(1)@127.0.1.1:47878
> I0910 05:57:33.275354 17651 master.cpp:1331] Received registration request from scheduler(1)@127.0.1.1:47878
> I0910 05:57:33.275554 17651 master.cpp:1291] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0910 05:57:33.276001 17651 master.cpp:1390] Registering framework 20140910-055728-16842879-47878-17625-0000 at scheduler(1)@127.0.1.1:47878
> I0910 05:57:33.276430 17655 scheduler.cpp:582] Enqueuing event 1 from master@127.0.1.1:47878
> Received a REGISTERED event
> Framework '20140910-055728-16842879-47878-17625-0000' registered with Master '20140910-055728-16842879-47878-17625'
> I0910 05:57:33.277101 17650 hierarchical_allocator_process.hpp:329] Added framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.277266 17650 hierarchical_allocator_process.hpp:734] Offering cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-1 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.277539 17650 hierarchical_allocator_process.hpp:734] Offering cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-2 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.277745 17650 hierarchical_allocator_process.hpp:734] Offering cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-0 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.278036 17650 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 830793ns
> I0910 05:57:33.278403 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-0 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:33.278640 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-1 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-2 (trusty)
> I0910 05:57:33.278811 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-2 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:33.278985 17651 master.cpp:3600] Sending 3 offers to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.279233 17654 scheduler.cpp:582] Enqueuing event 3 from master@127.0.1.1:47878
> Received an OFFERS event
> Offer '20140910-055728-16842879-47878-17625-0' has cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> Starting task 0 on trusty
> Offer '20140910-055728-16842879-47878-17625-1' has cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> Starting task 1 on trusty
> Offer '20140910-055728-16842879-47878-17625-2' has cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000]
> Starting task 2 on trusty
> I0910 05:57:33.281414 17651 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-0 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:33.281597 17651 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-0 ] on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.281846 17651 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
> I0910 05:57:33.282474 17651 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-1 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-2 (trusty)
> I0910 05:57:33.282624 17651 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-1 ] on slave 20140910-055728-16842879-47878-17625-2 at slave(1)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.282870 17651 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
> I0910 05:57:33.283226 17651 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-2 with resources cpus(*):1; mem(*):1986; disk(*):24988; ports(*):[31000-32000] on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:33.283448 17651 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-2 ] on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.283574 17651 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 2 as user 'jenkins'
> I0910 05:57:33.284101 17651 master.hpp:833] Adding task 0 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:33.284225 17651 master.cpp:2350] Launching task 0 of framework 20140910-055728-16842879-47878-17625-0000 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:33.284483 17652 slave.cpp:1011] Got assigned task 0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.284999 17652 slave.cpp:1121] Launching task 0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.286766 17652 slave.cpp:1231] Queuing task '0' for executor default of framework '20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.287153 17655 containerizer.cpp:394] Starting container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000'
> I0910 05:57:33.288884 17655 launcher.cpp:137] Forked child with pid '17664' for container '18a24ca7-5191-4694-a598-0f189d096b58'
> I0910 05:57:33.290501 17655 containerizer.cpp:510] Fetching URIs for container '18a24ca7-5191-4694-a598-0f189d096b58' using command '/var/jenkins/workspace/mesos-ubuntu-14.04-gcc/src/mesos-fetcher'
> I0910 05:57:33.290899 17652 slave.cpp:552] Successfully attached file '/tmp/mesos-SUO0qf/1/slaves/20140910-055728-16842879-47878-17625-0/frameworks/20140910-055728-16842879-47878-17625-0000/executors/default/runs/18a24ca7-5191-4694-a598-0f189d096b58'
> I0910 05:57:33.293633 17656 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):24988; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):24988; ports(*):[31000-32000]) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.294098 17656 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-0 for 5secs
> I0910 05:57:33.294687 17651 master.hpp:833] Adding task 1 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-2 (trusty)
> I0910 05:57:33.294816 17651 master.cpp:2350] Launching task 1 of framework 20140910-055728-16842879-47878-17625-0000 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-2 at slave(1)@127.0.1.1:47878 (trusty)
> I0910 05:57:33.295208 17653 slave.cpp:1011] Got assigned task 1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.295580 17653 slave.cpp:1121] Launching task 1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.297366 17654 containerizer.cpp:394] Starting container 'e1250d9f-c67b-429a-a9b1-f5aca0931026' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000'
> I0910 05:57:33.299192 17654 launcher.cpp:137] Forked child with pid '17667' for container 'e1250d9f-c67b-429a-a9b1-f5aca0931026'
> I0910 05:57:33.300361 17654 containerizer.cpp:510] Fetching URIs for container 'e1250d9f-c67b-429a-a9b1-f5aca0931026' using command '/var/jenkins/workspace/mesos-ubuntu-14.04-gcc/src/mesos-fetcher'
> I0910 05:57:33.301656 17653 slave.cpp:1231] Queuing task '1' for executor default of framework '20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.302314 17650 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):24988; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):24988; ports(*):[31000-32000]) on slave 20140910-055728-16842879-47878-17625-2 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.302688 17650 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-2 for 5secs
> I0910 05:57:33.302956 17653 slave.cpp:552] Successfully attached file '/tmp/mesos-SUO0qf/0/slaves/20140910-055728-16842879-47878-17625-2/frameworks/20140910-055728-16842879-47878-17625-0000/executors/default/runs/e1250d9f-c67b-429a-a9b1-f5aca0931026'
> I0910 05:57:33.302527 17651 master.hpp:833] Adding task 2 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:33.311622 17651 master.cpp:2350] Launching task 2 of framework 20140910-055728-16842879-47878-17625-0000 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:33.325979 17650 slave.cpp:1011] Got assigned task 2 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.326410 17650 slave.cpp:1121] Launching task 2 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.330621 17650 slave.cpp:1231] Queuing task '2' for executor default of framework '20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.332466 17650 slave.cpp:552] Successfully attached file '/tmp/mesos-SUO0qf/2/slaves/20140910-055728-16842879-47878-17625-1/frameworks/20140910-055728-16842879-47878-17625-0000/executors/default/runs/f0e1c021-006c-446c-a30f-b34e3f92a847'
> I0910 05:57:33.332404 17652 containerizer.cpp:394] Starting container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000'
> I0910 05:57:33.338142 17652 launcher.cpp:137] Forked child with pid '17692' for container 'f0e1c021-006c-446c-a30f-b34e3f92a847'
> I0910 05:57:33.338976 17652 containerizer.cpp:510] Fetching URIs for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' using command '/var/jenkins/workspace/mesos-ubuntu-14.04-gcc/src/mesos-fetcher'
> I0910 05:57:33.341742 17651 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):24988; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):24988; ports(*):[31000-32000]) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:33.354110 17651 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-1 for 5secs
> I0910 05:57:35.231225 17653 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 285213ns
> I0910 05:57:36.904172 17656 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 151696ns
> I0910 05:57:36.915994 17649 slave.cpp:2542] Monitoring executor 'default' of framework '20140910-055728-16842879-47878-17625-0000' in container '18a24ca7-5191-4694-a598-0f189d096b58'
> I0910 05:57:36.936676 17649 slave.cpp:2542] Monitoring executor 'default' of framework '20140910-055728-16842879-47878-17625-0000' in container 'e1250d9f-c67b-429a-a9b1-f5aca0931026'
> I0910 05:57:36.972208 17650 slave.cpp:2542] Monitoring executor 'default' of framework '20140910-055728-16842879-47878-17625-0000' in container 'f0e1c021-006c-446c-a30f-b34e3f92a847'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0910 05:57:39.620908 17768 process.cpp:1771] libprocess is initialized on 127.0.1.1:43121 for 8 cpus
> I0910 05:57:39.631126 17768 logging.cpp:177] Logging to STDERR
> I0910 05:57:39.632813 17768 exec.cpp:132] Version: 0.21.0
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0910 05:57:39.642254 17782 process.cpp:1771] libprocess is initialized on 127.0.1.1:58767 for 8 cpus
> II0910 05:57:39.643565 17782 logging.cpp:177] Logging to STDERR
> I0910 05:57:39.643273 17835 exec.cpp:182] Executor started at: executor(1)@127.0.1.1:43121 with pid 17768
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> 0910 05:57:39.645064 17782 exec.cpp:132] Version: 0.21.0
> I0910 05:57:39.647562 17799 process.cpp:1771] libprocess is initialized on 127.0.1.1:48970 for 8 cpus
> I0910 05:57:39.651067 17799 logging.cpp:177] Logging to STDERR
> II0910 05:57:39.652591 17799 exec.cpp:132] Version: 0.21.0
> 0910 05:57:39.654654 17839 exec.cpp:182] Executor started at: executor(1)@127.0.1.1:58767 with pid 17782
> I0910 05:57:39.659142 17853 exec.cpp:182] Executor started at: executor(1)@127.0.1.1:48970 with pid 17799
> I0910 05:57:39.661471 17650 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 179392ns
> I0910 05:57:39.662075 17653 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0910 05:57:39.663228 17649 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:39.667678 17649 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:39.668686 17654 slave.cpp:1741] Got registration for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.669030 17656 slave.cpp:1741] Got registration for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.669173 17652 slave.cpp:1741] Got registration for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.671890 17654 slave.cpp:1859] Flushing queued task 0 for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.672714 17656 slave.cpp:1859] Flushing queued task 1 for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.673509 17652 slave.cpp:1859] Flushing queued task 2 for executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.678136 17657 process.cpp:1143] Socket error while receiving: Transport endpoint is not connected
> I0910 05:57:39.679213 17837 exec.cpp:206] Executor registered on slave 20140910-055728-16842879-47878-17625-0
> Registered executor on trusty
> I0910 05:57:39.680366 17837 exec.cpp:218] Executor::registered took 54586ns
> I0910 05:57:39.682168 17834 exec.cpp:293] Executor asked to run task '0'
> Starting task 0
> Finishing task 0
> I0910 05:57:39.682723 17834 exec.cpp:302] Executor::launchTask took 88644ns
> I0910 05:57:39.683670 17834 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.684591 17834 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.698040 17851 exec.cpp:206] Executor registered on slave 20140910-055728-16842879-47878-17625-1
> Registered executor on trusty
> I0910 05:57:39.698761 17851 exec.cpp:218] Executor::registered took 30395ns
> I0910 05:57:39.699911 17845 exec.cpp:206] Executor registered on slave 20140910-055728-16842879-47878-17625-2
> Registered executor on trusty
> I0910 05:57:39.700625 17845 exec.cpp:218] Executor::registered took 26516ns
> I0910 05:57:39.701577 17652 slave.cpp:2093] Handling status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:43121
> I0910 05:57:39.702487 17851 exec.cpp:293] Executor asked to run task '2'
> Starting task 2
> Finishing task 2
> I0910 05:57:39.702555 17851 exec.cpp:302] Executor::launchTask took 41027ns
> I0910 05:57:39.703290 17851 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.704581 17851 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.705202 17653 slave.cpp:2093] Handling status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:48970
> I0910 05:57:39.705991 17653 slave.cpp:2093] Handling status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:48970
> I0910 05:57:39.709903 17653 slave.cpp:3913] Terminating task 2
> I0910 05:57:39.706425 17652 slave.cpp:2093] Handling status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:43121
> I0910 05:57:39.710875 17652 slave.cpp:3913] Terminating task 0
> I0910 05:57:39.706163 17654 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.711388 17654 status_update_manager.cpp:499] Creating StatusUpdate stream for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.711824 17654 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:39.712252 17654 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.706459 17650 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.712693 17650 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.712867 17650 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:39.713063 17650 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.713243 17650 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> I0910 05:57:39.713523 17650 slave.cpp:2250] Status update manager successfully handled status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.713647 17650 slave.cpp:2256] Sending acknowledgement for status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:43121
> I0910 05:57:39.714083 17653 slave.cpp:2250] Status update manager successfully handled status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> Received an UPDATE event
> Task 2 is in state TASK_RUNNING
> I0910 05:57:39.716528 17832 exec.cpp:339] Executor received status update acknowledgement 55307861-72e0-4ac8-8403-2fca05a4a68a for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.716927 17653 slave.cpp:2256] Sending acknowledgement for status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:48970
> I0910 05:57:39.712461 17654 master.cpp:3178] Status update TASK_RUNNING (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.716189 17650 slave.cpp:2250] Status update manager successfully handled status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.717636 17650 slave.cpp:2256] Sending acknowledgement for status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:43121
> I0910 05:57:39.718108 17854 exec.cpp:339] Executor received status update acknowledgement 861cd179-d59f-4f8b-a3b7-9f9546a906f1 for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.717465 17654 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.718881 17832 exec.cpp:339] Executor received status update acknowledgement fbef7f4c-95fe-4789-8c41-ded8e8650a6c for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.719624 17653 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.720046 17653 slave.cpp:2250] Status update manager successfully handled status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.720172 17653 slave.cpp:2256] Sending acknowledgement for status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:48970
> I0910 05:57:39.719812 17654 master.cpp:3178] Status update TASK_RUNNING (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.720587 17654 master.cpp:2693] Forwarding status update acknowledgement 861cd179-d59f-4f8b-a3b7-9f9546a906f1 for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.719859 17649 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> Received an UPDATE event
> Task 0 is in state TASK_RUNNING
> I0910 05:57:39.722578 17854 exec.cpp:339] Executor received status update acknowledgement 3c8e2b9d-6182-403e-b39f-01482d3cd475 for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.723086 17650 master.cpp:2693] Forwarding status update acknowledgement 55307861-72e0-4ac8-8403-2fca05a4a68a for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.723433 17650 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.723666 17650 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:39.723937 17650 master.cpp:3212] Forwarding status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.724074 17654 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: 55307861-72e0-4ac8-8403-2fca05a4a68a) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.723613 17653 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.724392 17653 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:39.724606 17650 master.cpp:3178] Status update TASK_FINISHED (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.724863 17650 master.hpp:851] Removing task 0 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:39.725108 17650 master.cpp:3212] Forwarding status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.725355 17650 master.cpp:3178] Status update TASK_FINISHED (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.725539 17650 master.hpp:851] Removing task 2 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:39.724797 17656 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: 861cd179-d59f-4f8b-a3b7-9f9546a906f1) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.724750 17654 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> I0910 05:57:39.726076 17654 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> I0910 05:57:39.725293 17653 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.726600 17653 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> Received an UPDATE event
> Task 0 is in state TASK_FINISHED
> Received an UPDATE event
> Task 2 is in state TASK_FINISHED
> I0910 05:57:39.727675 17653 master.cpp:2693] Forwarding status update acknowledgement fbef7f4c-95fe-4789-8c41-ded8e8650a6c for task 0 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.727844 17653 master.cpp:2693] Forwarding status update acknowledgement 3c8e2b9d-6182-403e-b39f-01482d3cd475 for task 2 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:39.728099 17653 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.728255 17653 status_update_manager.cpp:530] Cleaning up status update stream for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.728492 17653 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: 3c8e2b9d-6182-403e-b39f-01482d3cd475) for task 2 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.728638 17653 slave.cpp:3952] Completing task 2
> I0910 05:57:39.728037 17654 status_update_manager.cpp:398] Received status update acknowledgement (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.728899 17654 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.729096 17654 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: fbef7f4c-95fe-4789-8c41-ded8e8650a6c) for task 0 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:39.729233 17654 slave.cpp:3952] Completing task 0
> I0910 05:57:40.666843 17652 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.801198 17652 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.801400 17652 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 1.134627446secs
> I0910 05:57:41.800956 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:41.802037 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:41.816066 17655 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-3 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:41.816249 17655 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-4 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:41.816329 17655 master.cpp:3600] Sending 2 offers to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.816572 17655 scheduler.cpp:582] Enqueuing event 3 from master@127.0.1.1:47878
> Received an OFFERS event
> Offer '20140910-055728-16842879-47878-17625-3' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> Starting task 3 on trusty
> Offer '20140910-055728-16842879-47878-17625-4' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> Starting task 4 on trusty
> I0910 05:57:41.819516 17649 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-3 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:41.819804 17649 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-3 ] on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.820106 17649 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 3 as user 'jenkins'
> I0910 05:57:41.820590 17649 master.hpp:833] Adding task 3 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:41.820824 17649 master.cpp:2350] Launching task 3 of framework 20140910-055728-16842879-47878-17625-0000 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.821173 17649 slave.cpp:1011] Got assigned task 3 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.821569 17649 slave.cpp:1121] Launching task 3 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.821424 17656 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):24988; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):24988; ports(*):[31000-32000]) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.821980 17656 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-0 for 5secs
> I0910 05:57:41.822149 17649 slave.cpp:1253] Sending task '3' to executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.822984 17831 exec.cpp:293] Executor asked to run task '3'
> Starting task 3
> Finishing task 3
> I0910 05:57:41.823040 17831 exec.cpp:302] Executor::launchTask took 24799ns
> I0910 05:57:41.823709 17831 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.824403 17831 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.829969 17649 slave.cpp:2093] Handling status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:43121
> I0910 05:57:41.830526 17650 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.830692 17650 status_update_manager.cpp:499] Creating StatusUpdate stream for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.830993 17650 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:41.831281 17650 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.831475 17650 master.cpp:3178] Status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.831720 17649 slave.cpp:2093] Handling status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:43121
> I0910 05:57:41.831897 17649 slave.cpp:3913] Terminating task 3
> I0910 05:57:41.832270 17649 slave.cpp:2250] Status update manager successfully handled status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.832437 17649 slave.cpp:2256] Sending acknowledgement for status update TASK_RUNNING (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:43121
> I0910 05:57:41.832806 17656 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.832996 17649 slave.cpp:2250] Status update manager successfully handled status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.833143 17649 slave.cpp:2256] Sending acknowledgement for status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:43121
> I0910 05:57:41.833706 17656 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-4 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:41.833989 17656 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-4 ] on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.834161 17656 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 4 as user 'jenkins'
> I0910 05:57:41.834524 17656 master.hpp:833] Adding task 4 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:41.834687 17656 master.cpp:2350] Launching task 4 of framework 20140910-055728-16842879-47878-17625-0000 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.834965 17656 slave.cpp:1011] Got assigned task 4 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.835175 17656 slave.cpp:1121] Launching task 4 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.835368 17656 slave.cpp:1253] Sending task '4' to executor 'default' of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.835891 17854 exec.cpp:293] Executor asked to run task '4'
> Starting task 4
> Finishing task 4
> I0910 05:57:41.835945 17854 exec.cpp:302] Executor::launchTask took 32724ns
> I0910 05:57:41.836642 17854 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.837334 17854 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.838176 17656 slave.cpp:2093] Handling status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:48970
> I0910 05:57:41.838529 17656 slave.cpp:2093] Handling status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 from executor(1)@127.0.1.1:48970
> I0910 05:57:41.838681 17656 slave.cpp:3913] Terminating task 4
> I0910 05:57:41.838935 17656 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):24988; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):24988; ports(*):[31000-32000]) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.839125 17656 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-1 for 5secs
> I0910 05:57:41.839421 17656 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.839643 17656 status_update_manager.cpp:499] Creating StatusUpdate stream for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.839978 17656 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> II0910 05:57:41.840670 17656 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.840859 17650 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> 0910 05:57:41.840445 17832 exec.cpp:339] Executor received status update acknowledgement b5b9358e-d2be-4649-bac7-aa99d4519061 for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.841294 17650 master.cpp:3178] Status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.840879 17649 slave.cpp:2250] Status update manager successfully handled status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.841652 17832 exec.cpp:339] Executor received status update acknowledgement 89b7a91b-732f-4fa1-a9cd-571284198c84 for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.841976 17649 slave.cpp:2256] Sending acknowledgement for status update TASK_RUNNING (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:48970
> I0910 05:57:41.842403 17853 exec.cpp:339] Executor received status update acknowledgement ec09f12a-c298-412b-ba17-9926e9cc6568 for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.844559 17649 slave.cpp:2250] Status update manager successfully handled status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.844704 17649 slave.cpp:2256] Sending acknowledgement for status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to executor(1)@127.0.1.1:48970
> I0910 05:57:41.845149 17655 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> I0910 05:57:41.845427 17850 exec.cpp:339] Executor received status update acknowledgement fb8621db-8f77-4d6a-9e5e-0870357c137d for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.846074 17655 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> Received an UPDATE event
> Task 3 is in state TASK_RUNNING
> I0910 05:57:41.846928 17649 master.cpp:2693] Forwarding status update acknowledgement b5b9358e-d2be-4649-bac7-aa99d4519061 for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.847121 17649 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.847259 17649 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:41.847470 17649 master.cpp:3212] Forwarding status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.847589 17650 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: b5b9358e-d2be-4649-bac7-aa99d4519061) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.847764 17649 master.cpp:3178] Status update TASK_FINISHED (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.847946 17649 master.hpp:851] Removing task 3 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:41.848160 17649 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.847895 17651 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> Received an UPDATE event
> Task 4 is in state TASK_RUNNING
> I0910 05:57:41.848832 17656 master.cpp:2693] Forwarding status update acknowledgement ec09f12a-c298-412b-ba17-9926e9cc6568 for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.848984 17656 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.849105 17656 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to master@127.0.1.1:47878
> I0910 05:57:41.849303 17656 master.cpp:3212] Forwarding status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.849454 17656 master.cpp:3178] Status update TASK_FINISHED (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000 from slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.849617 17656 master.hpp:851] Removing task 4 with resources cpus(*):1; mem(*):32 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:41.849576 17654 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: ec09f12a-c298-412b-ba17-9926e9cc6568) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.850008 17654 scheduler.cpp:582] Enqueuing event 5 from master@127.0.1.1:47878
> I0910 05:57:41.850278 17656 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> Received an UPDATE event
> Task 3 is in state TASK_FINISHED
> I0910 05:57:41.852195 17654 master.cpp:2693] Forwarding status update acknowledgement 89b7a91b-732f-4fa1-a9cd-571284198c84 for task 3 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.852360 17654 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.852505 17654 status_update_manager.cpp:530] Cleaning up status update stream for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.852720 17654 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: 89b7a91b-732f-4fa1-a9cd-571284198c84) for task 3 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.852838 17654 slave.cpp:3952] Completing task 3
> Received an UPDATE event
> Task 4 is in state TASK_FINISHED
> I0910 05:57:41.853394 17650 master.cpp:2693] Forwarding status update acknowledgement fb8621db-8f77-4d6a-9e5e-0870357c137d for task 4 of framework 20140910-055728-16842879-47878-17625-0000 to slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty)
> I0910 05:57:41.853546 17650 status_update_manager.cpp:398] Received status update acknowledgement (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.853663 17650 status_update_manager.cpp:530] Cleaning up status update stream for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.853899 17650 slave.cpp:1681] Status update manager successfully handled status update acknowledgement (UUID: fb8621db-8f77-4d6a-9e5e-0870357c137d) for task 4 of framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:41.854012 17650 slave.cpp:3952] Completing task 4
> I0910 05:57:42.801822 17651 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.801992 17651 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.802090 17651 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 419462ns
> I0910 05:57:42.802167 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-5 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:42.802252 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-6 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:42.802289 17651 master.cpp:3600] Sending 2 offers to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.802376 17651 scheduler.cpp:582] Enqueuing event 3 from master@127.0.1.1:47878
> Received an OFFERS event
> Offer '20140910-055728-16842879-47878-17625-5' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> Offer '20140910-055728-16842879-47878-17625-6' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> I0910 05:57:42.803580 17655 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:42.803609 17655 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:42.803942 17654 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-5 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:42.804179 17654 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-5 ] on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.804566 17654 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.804756 17654 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-1 for 5secs
> I0910 05:57:42.805166 17651 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-6 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:42.805387 17651 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-6 ] on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.805716 17651 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:42.806035 17651 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-0 for 5secs
> I0910 05:57:43.803367 17649 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:44.551349 17649 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:44.551429 17649 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 748.158881ms
> I0910 05:57:44.547655 17655 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:44.553855 17655 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:44.735302 17653 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0910 05:57:45.416501 17653 slave.cpp:2329] Received ping from slave-observer(1)@127.0.1.1:47878
> I0910 05:57:45.416576 17653 slave.cpp:2329] Received ping from slave-observer(2)@127.0.1.1:47878
> I0910 05:57:45.416594 17653 slave.cpp:2329] Received ping from slave-observer(3)@127.0.1.1:47878
> I0910 05:57:45.551782 17653 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:45.551928 17653 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:45.552000 17653 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 332766ns
> I0910 05:57:45.555125 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:45.555186 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:46.553287 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:46.553613 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:46.553843 17654 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 750574ns
> I0910 05:57:46.555428 17656 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:46.555627 17656 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:47.555145 17652 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:47.556267 17652 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:47.556488 17652 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 1.756733ms
> I0910 05:57:47.556171 17649 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:47.556980 17649 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:48.557112 17650 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.557466 17650 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.557694 17650 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 797016ns
> I0910 05:57:48.557956 17654 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-7 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:48.558389 17654 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-8 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:48.558573 17654 master.cpp:3600] Sending 2 offers to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.558809 17654 scheduler.cpp:582] Enqueuing event 3 from master@127.0.1.1:47878
> I0910 05:57:48.558171 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:48.559444 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> Received an OFFERS event
> Offer '20140910-055728-16842879-47878-17625-7' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> Offer '20140910-055728-16842879-47878-17625-8' has mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1
> I0910 05:57:48.560304 17653 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-7 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:48.560473 17653 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-7 ] on slave 20140910-055728-16842879-47878-17625-1 at slave(3)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.560760 17653 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-1 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.560899 17653 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-1 for 5secs
> I0910 05:57:48.561218 17654 master.hpp:871] Removing offer 20140910-055728-16842879-47878-17625-8 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:48.561393 17654 master.cpp:2201] Processing reply for offers: [ 20140910-055728-16842879-47878-17625-8 ] on slave 20140910-055728-16842879-47878-17625-0 at slave(2)@127.0.1.1:47878 (trusty) for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.561641 17654 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1) on slave 20140910-055728-16842879-47878-17625-0 from framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:48.561839 17654 hierarchical_allocator_process.hpp:599] Framework 20140910-055728-16842879-47878-17625-0000 filtered slave 20140910-055728-16842879-47878-17625-0 for 5secs
> I0910 05:57:49.558950 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:49.559320 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:49.559451 17654 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 596333ns
> I0910 05:57:49.560204 17655 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:49.560402 17655 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:49.735908 17655 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0910 05:57:50.560423 17653 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:50.630172 17653 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:50.630321 17653 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 69.980064ms
> I0910 05:57:50.631424 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:50.631456 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:51.631702 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:51.632220 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:51.632555 17649 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:51.632755 17649 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:51.632876 17649 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 1.33066ms
> I0910 05:57:52.632928 17650 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:52.633260 17650 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:52.633975 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:52.634240 17654 hierarchical_allocator_process.hpp:816] Filtered mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 for framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:52.634421 17654 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 540684ns
> I0910 05:57:53.634503 17653 monitor.cpp:140] Failed to collect resource usage for container '18a24ca7-5191-4694-a598-0f189d096b58' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: 18a24ca7-5191-4694-a598-0f189d096b58
> I0910 05:57:53.634903 17653 monitor.cpp:140] Failed to collect resource usage for container 'f0e1c021-006c-446c-a30f-b34e3f92a847' for executor 'default' of framework '20140910-055728-16842879-47878-17625-0000': Unknown container: f0e1c021-006c-446c-a30f-b34e3f92a847
> I0910 05:57:53.635594 17652 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:53.635949 17652 hierarchical_allocator_process.hpp:734] Offering mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:53.636235 17652 hierarchical_allocator_process.hpp:659] Performed allocation for 3 slaves in 778026ns
> I0910 05:57:53.636492 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-9 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-0 (trusty)
> I0910 05:57:53.636734 17651 master.hpp:861] Adding offer 20140910-055728-16842879-47878-17625-10 with resources mem(*):1986; disk(*):24988; ports(*):[31000-32000]; cpus(*):1 on slave 20140910-055728-16842879-47878-17625-1 (trusty)
> I0910 05:57:53.636926 17651 master.cpp:3600] Sending 2 offers to framework 20140910-055728-16842879-47878-17625-0000
> I0910 05:57:53.637140 17651 scheduler.cpp:582] Enqueuing event 3 from master@127.0.1.1:47878
> ...
> {noformat}
> {noformat:title=task 1 is never launched by the executor}
> grep "Executor asked to run" ExamplesTest.LowLevelSchedulerLibproc.txt
> I0910 05:57:39.682168 17834 exec.cpp:293] Executor asked to run task '0'
> I0910 05:57:39.702487 17851 exec.cpp:293] Executor asked to run task '2'
> I0910 05:57:41.822984 17831 exec.cpp:293] Executor asked to run task '3'
> I0910 05:57:41.835891 17854 exec.cpp:293] Executor asked to run task '4'
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)