[jira] [Updated] (MESOS-1709) ExamplesTest.NoExecutorFramework is flaky

["Cody Maloney (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/MESOS-1709?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Cody Maloney updated MESOS-1709:
--------------------------------
    Labels: flaky  (was: )

> ExamplesTest.NoExecutorFramework is flaky
> -----------------------------------------
>
>                 Key: MESOS-1709
>                 URL: https://issues.apache.org/jira/browse/MESOS-1709
>             Project: Mesos
>          Issue Type: Bug
>          Components: test
>            Reporter: Vinod Kone
>              Labels: flaky
>
> Seen this happen couple of times on Twitter CI machines. Looks like the slave sends TASK_FAILED for one of the executors because it got a executorTerminated() signal before it got a TASK_FINISHED signal.
> {code}
> [ RUN      ] ExamplesTest.NoExecutorFramework
> Using temporary directory '/tmp/ExamplesTest_NoExecutorFramework_dZZzd6'
> Enabling authentication for the framework
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:25.623885  5879 process.cpp:1770] libprocess is initialized on 192.168.122.164:53897 for 8 cpus
> I0815 18:39:25.624589  5879 logging.cpp:172] Logging to STDERR
> I0815 18:39:25.627943  5879 leveldb.cpp:176] Opened db in 897745ns
> I0815 18:39:25.628557  5879 leveldb.cpp:183] Compacted db in 467234ns
> I0815 18:39:25.628706  5879 leveldb.cpp:198] Created db iterator in 11396ns
> I0815 18:39:25.628939  5879 leveldb.cpp:204] Seeked to beginning of db in 1391ns
> I0815 18:39:25.629060  5879 leveldb.cpp:273] Iterated through 0 keys in the db in 678ns
> I0815 18:39:25.629261  5879 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0815 18:39:25.630502  5909 recover.cpp:425] Starting replica recovery
> I0815 18:39:25.630935  5909 recover.cpp:451] Replica is in EMPTY status
> I0815 18:39:25.631501  5909 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0815 18:39:25.631804  5909 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0815 18:39:25.632524  5909 recover.cpp:542] Updating replica status to STARTING
> I0815 18:39:25.632935  5909 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 48908ns
> I0815 18:39:25.633219  5909 replica.cpp:320] Persisted replica status to STARTING
> I0815 18:39:25.633545  5909 recover.cpp:451] Replica is in STARTING status
> I0815 18:39:25.634224  5905 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0815 18:39:25.634405  5905 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0815 18:39:25.634724  5909 recover.cpp:542] Updating replica status to VOTING
> I0815 18:39:25.634948  5908 master.cpp:286] Master 20140815-183925-2759502016-53897-5879 (fedora-20) started on 192.168.122.164:53897
> I0815 18:39:25.635123  5908 master.cpp:323] Master only allowing authenticated frameworks to register
> I0815 18:39:25.635311  5908 master.cpp:330] Master allowing unauthenticated slaves to register
> I0815 18:39:25.635455  5908 credentials.hpp:36] Loading credentials for authentication from '/tmp/ExamplesTest_NoExecutorFramework_dZZzd6/credentials'
> W0815 18:39:25.635658  5908 credentials.hpp:51] Permissions on credentials file '/tmp/ExamplesTest_NoExecutorFramework_dZZzd6/credentials' are too open. It is recommended that your credentials file is NOT accessible by others.
> I0815 18:39:25.635861  5908 master.cpp:357] Authorization enabled
> I0815 18:39:25.636286  5910 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@192.168.122.164:53897
> I0815 18:39:25.636443  5907 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0815 18:39:25.637657  5908 master.cpp:1196] The newly elected leader is master@192.168.122.164:53897 with id 20140815-183925-2759502016-53897-5879
> I0815 18:39:25.638296  5908 master.cpp:1209] Elected as the leading master!
> I0815 18:39:25.638254  5906 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 42875ns
> I0815 18:39:25.638552  5906 replica.cpp:320] Persisted replica status to VOTING
> I0815 18:39:25.638737  5906 recover.cpp:556] Successfully joined the Paxos group
> I0815 18:39:25.638926  5906 recover.cpp:440] Recover process terminated
> I0815 18:39:25.639225  5908 master.cpp:1027] Recovering from registrar
> I0815 18:39:25.639457  5907 registrar.cpp:313] Recovering registrar
> I0815 18:39:25.639850  5907 log.cpp:656] Attempting to start the writer
> I0815 18:39:25.640336  5907 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0815 18:39:25.640530  5907 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 37820ns
> I0815 18:39:25.640714  5907 replica.cpp:342] Persisted promised to 1
> I0815 18:39:25.641010  5907 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0815 18:39:25.641438  5907 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0815 18:39:25.641646  5907 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 24213ns
> I0815 18:39:25.641798  5907 replica.cpp:676] Persisted action at 0
> I0815 18:39:25.638136  5879 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0815 18:39:25.644611  5904 replica.cpp:508] Replica received write request for position 0
> I0815 18:39:25.644770  5904 leveldb.cpp:438] Reading position from leveldb took 32089ns
> I0815 18:39:25.644966  5904 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 21643ns
> I0815 18:39:25.645110  5904 replica.cpp:676] Persisted action at 0
> I0815 18:39:25.645392  5904 replica.cpp:655] Replica received learned notice for position 0
> I0815 18:39:25.645607  5904 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 17302ns
> I0815 18:39:25.645766  5904 replica.cpp:676] Persisted action at 0
> I0815 18:39:25.645895  5904 replica.cpp:661] Replica learned NOP action at position 0
> I0815 18:39:25.646149  5904 log.cpp:672] Writer started with ending position 0
> I0815 18:39:25.646587  5904 leveldb.cpp:438] Reading position from leveldb took 11426ns
> I0815 18:39:25.647692  5904 registrar.cpp:346] Successfully fetched the registry (0B)
> I0815 18:39:25.649070  5904 registrar.cpp:422] Attempting to update the 'registry'
> I0815 18:39:25.649006  5909 slave.cpp:167] Slave started on 1)@192.168.122.164:53897
> I0815 18:39:25.649868  5909 slave.cpp:278] Slave resources: cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:25.650450  5909 slave.cpp:306] Slave hostname: fedora-20
> I0815 18:39:25.650593  5909 slave.cpp:307] Slave checkpoint: true
> I0815 18:39:25.651796  5909 state.cpp:33] Recovering state from '/tmp/mesos-KqTEZx/0/meta'
> I0815 18:39:25.648824  5879 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0815 18:39:25.652362  5906 status_update_manager.cpp:193] Recovering status update manager
> I0815 18:39:25.652549  5906 containerizer.cpp:252] Recovering containerizer
> I0815 18:39:25.653365  5909 slave.cpp:3195] Finished recovery
> I0815 18:39:25.654274  5906 log.cpp:680] Attempting to append 130 bytes to the log
> I0815 18:39:25.654615  5906 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0815 18:39:25.655019  5906 replica.cpp:508] Replica received write request for position 1
> I0815 18:39:25.655351  5906 leveldb.cpp:343] Persisting action (149 bytes) to leveldb took 189673ns
> I0815 18:39:25.655488  5906 replica.cpp:676] Persisted action at 1
> I0815 18:39:25.655925  5906 replica.cpp:655] Replica received learned notice for position 1
> I0815 18:39:25.656082  5906 leveldb.cpp:343] Persisting action (151 bytes) to leveldb took 22516ns
> I0815 18:39:25.656287  5906 replica.cpp:676] Persisted action at 1
> I0815 18:39:25.656415  5906 replica.cpp:661] Replica learned APPEND action at position 1
> I0815 18:39:25.656862  5906 log.cpp:699] Attempting to truncate the log to 1
> I0815 18:39:25.657024  5906 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0815 18:39:25.657323  5906 replica.cpp:508] Replica received write request for position 2
> I0815 18:39:25.657493  5906 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18646ns
> I0815 18:39:25.657675  5906 replica.cpp:676] Persisted action at 2
> I0815 18:39:25.658062  5908 replica.cpp:655] Replica received learned notice for position 2
> I0815 18:39:25.658244  5908 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 22431ns
> I0815 18:39:25.658440  5908 leveldb.cpp:401] Deleting ~1 keys from leveldb took 13804ns
> I0815 18:39:25.658577  5908 replica.cpp:676] Persisted action at 2
> I0815 18:39:25.658725  5908 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0815 18:39:25.659044  5904 registrar.cpp:479] Successfully updated 'registry'
> I0815 18:39:25.659265  5904 registrar.cpp:372] Successfully recovered registrar
> I0815 18:39:25.659961  5904 master.cpp:1054] Recovered 0 slaves from the Registry (94B) ; allowing 10mins for slaves to re-register
> I0815 18:39:25.659793  5908 slave.cpp:167] Slave started on 2)@192.168.122.164:53897
> I0815 18:39:25.660451  5908 slave.cpp:278] Slave resources: cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:25.659881  5909 slave.cpp:589] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.661017  5909 slave.cpp:625] No credentials provided. Attempting to register without authentication
> I0815 18:39:25.661216  5903 status_update_manager.cpp:167] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.660976  5908 slave.cpp:306] Slave hostname: fedora-20
> I0815 18:39:25.661545  5908 slave.cpp:307] Slave checkpoint: true
> I0815 18:39:25.662052  5908 state.cpp:33] Recovering state from '/tmp/mesos-KqTEZx/1/meta'
> I0815 18:39:25.662428  5908 status_update_manager.cpp:193] Recovering status update manager
> I0815 18:39:25.662627  5908 containerizer.cpp:252] Recovering containerizer
> I0815 18:39:25.662576  5909 slave.cpp:636] Detecting new master
> I0815 18:39:25.659757  5879 containerizer.cpp:89] Using isolation: posix/cpu,posix/mem
> I0815 18:39:25.663452  5908 slave.cpp:3195] Finished recovery
> I0815 18:39:25.664305  5908 slave.cpp:589] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.665261  5909 slave.cpp:167] Slave started on 3)@192.168.122.164:53897
> I0815 18:39:25.665673  5909 slave.cpp:278] Slave resources: cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:25.665961  5908 slave.cpp:625] No credentials provided. Attempting to register without authentication
> I0815 18:39:25.666113  5904 status_update_manager.cpp:167] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.666227  5909 slave.cpp:306] Slave hostname: fedora-20
> I0815 18:39:25.666501  5909 slave.cpp:307] Slave checkpoint: true
> I0815 18:39:25.666779  5908 slave.cpp:636] Detecting new master
> I0815 18:39:25.667382  5909 state.cpp:33] Recovering state from '/tmp/mesos-KqTEZx/2/meta'
> I0815 18:39:25.667593  5909 status_update_manager.cpp:193] Recovering status update manager
> I0815 18:39:25.667778  5909 containerizer.cpp:252] Recovering containerizer
> I0815 18:39:25.668346  5909 slave.cpp:3195] Finished recovery
> I0815 18:39:25.669229  5909 slave.cpp:589] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.669472  5910 status_update_manager.cpp:167] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.669617  5909 slave.cpp:625] No credentials provided. Attempting to register without authentication
> I0815 18:39:25.669780  5909 slave.cpp:636] Detecting new master
> I0815 18:39:25.670081  5879 sched.cpp:139] Version: 0.20.0
> I0815 18:39:25.670409  5904 sched.cpp:235] New master detected at master@192.168.122.164:53897
> I0815 18:39:25.670573  5904 sched.cpp:285] Authenticating with master master@192.168.122.164:53897
> I0815 18:39:25.670831  5904 authenticatee.hpp:104] Initializing client SASL
> I0815 18:39:25.674437  5904 authenticatee.hpp:128] Creating new client SASL connection
> I0815 18:39:25.675029  5910 master.cpp:3612] Authenticating scheduler-06952f0b-12cb-4f08-a8a4-df3bf4c131bd@192.168.122.164:53897
> I0815 18:39:25.675345  5910 authenticator.hpp:94] Initializing server SASL
> I0815 18:39:25.675667  5910 auxprop.cpp:45] Initialized in-memory auxiliary property plugin
> I0815 18:39:25.675791  5910 authenticator.hpp:156] Creating new server SASL connection
> I0815 18:39:25.676455  5910 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0815 18:39:25.676641  5910 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0815 18:39:25.676808  5910 authenticator.hpp:262] Received SASL authentication start
> I0815 18:39:25.677012  5910 authenticator.hpp:384] Authentication requires more steps
> I0815 18:39:25.677222  5910 authenticatee.hpp:265] Received SASL authentication step
> I0815 18:39:25.677395  5910 authenticator.hpp:290] Received SASL authentication step
> I0815 18:39:25.677575  5910 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0815 18:39:25.677708  5910 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0815 18:39:25.677860  5910 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0815 18:39:25.677999  5910 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0815 18:39:25.678125  5910 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0815 18:39:25.678304  5910 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0815 18:39:25.678468  5910 authenticator.hpp:376] Authentication success
> I0815 18:39:25.678637  5906 authenticatee.hpp:305] Authentication success
> I0815 18:39:25.682234  5910 master.cpp:3652] Successfully authenticated principal 'test-principal' at scheduler-06952f0b-12cb-4f08-a8a4-df3bf4c131bd@192.168.122.164:53897
> I0815 18:39:25.682651  5906 sched.cpp:359] Successfully authenticated with master master@192.168.122.164:53897
> I0815 18:39:25.682795  5906 sched.cpp:478] Sending registration request to master@192.168.122.164:53897
> I0815 18:39:25.682986  5903 master.cpp:1315] Received registration request from scheduler-06952f0b-12cb-4f08-a8a4-df3bf4c131bd@192.168.122.164:53897
> I0815 18:39:25.683195  5903 master.cpp:1275] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0815 18:39:25.683444  5903 master.cpp:1374] Registering framework 20140815-183925-2759502016-53897-5879-0000 at scheduler-06952f0b-12cb-4f08-a8a4-df3bf4c131bd@192.168.122.164:53897
> I0815 18:39:25.683742  5903 hierarchical_allocator_process.hpp:329] Added framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.683914  5903 hierarchical_allocator_process.hpp:691] No resources available to allocate!
> I0815 18:39:25.684033  5903 hierarchical_allocator_process.hpp:653] Performed allocation for 0 slaves in 122032ns
> I0815 18:39:25.684248  5906 sched.cpp:409] Framework registered with 20140815-183925-2759502016-53897-5879-0000
> Registered!
> I0815 18:39:25.684543  5906 sched.cpp:423] Scheduler::registered took 132777ns
> I0815 18:39:25.780192  5908 slave.cpp:971] Will retry registration in 423.208575ms if necessary
> I0815 18:39:25.780313  5908 master.cpp:2811] Registering slave at slave(2)@192.168.122.164:53897 (fedora-20) with id 20140815-183925-2759502016-53897-5879-0
> I0815 18:39:25.780436  5908 registrar.cpp:422] Attempting to update the 'registry'
> I0815 18:39:25.781433  5908 log.cpp:680] Attempting to append 310 bytes to the log
> I0815 18:39:25.781482  5908 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0815 18:39:25.781648  5908 replica.cpp:508] Replica received write request for position 3
> I0815 18:39:25.781697  5908 leveldb.cpp:343] Persisting action (329 bytes) to leveldb took 31444ns
> I0815 18:39:25.781708  5908 replica.cpp:676] Persisted action at 3
> I0815 18:39:25.781826  5908 replica.cpp:655] Replica received learned notice for position 3
> I0815 18:39:25.781855  5908 leveldb.cpp:343] Persisting action (331 bytes) to leveldb took 14966ns
> I0815 18:39:25.781863  5908 replica.cpp:676] Persisted action at 3
> I0815 18:39:25.781870  5908 replica.cpp:661] Replica learned APPEND action at position 3
> I0815 18:39:25.782086  5908 registrar.cpp:479] Successfully updated 'registry'
> I0815 18:39:25.782786  5903 master.cpp:2851] Registered slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:25.782814  5903 master.cpp:4085] Adding slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:25.782919  5903 slave.cpp:754] Registered with master master@192.168.122.164:53897; given slave ID 20140815-183925-2759502016-53897-5879-0
> I0815 18:39:25.783123  5903 slave.cpp:767] Checkpointing SlaveInfo to '/tmp/mesos-KqTEZx/1/meta/slaves/20140815-183925-2759502016-53897-5879-0/slave.info'
> I0815 18:39:25.783537  5910 hierarchical_allocator_process.hpp:442] Added slave 20140815-183925-2759502016-53897-5879-0 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] available)
> I0815 18:39:25.784061  5910 hierarchical_allocator_process.hpp:728] Offering cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-0 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.784467  5910 hierarchical_allocator_process.hpp:673] Performed allocation for slave 20140815-183925-2759502016-53897-5879-0 in 438829ns
> I0815 18:39:25.784806  5909 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-0 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:25.785150  5909 master.cpp:3559] Sending 1 offers to framework 20140815-183925-2759502016-53897-5879-0000
> .Starting task 0 on fedora-20
> I0815 18:39:25.786145  5909 sched.cpp:546] Scheduler::resourceOffers took 593126ns
> I0815 18:39:25.786576  5909 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-0 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:25.786913  5909 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-0 ] on slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.787230  5909 master.cpp:2252] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
> I0815 18:39:25.787724  5909 master.hpp:829] Adding task 0 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:25.787916  5909 master.cpp:2318] Launching task 0 of framework 20140815-183925-2759502016-53897-5879-0000 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:25.783998  5903 slave.cpp:2324] Received ping from slave-observer(1)@192.168.122.164:53897
> I0815 18:39:25.788410  5903 slave.cpp:1002] Got assigned task 0 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.789026  5903 slave.cpp:1112] Launching task 0 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.789288  5905 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):752; ports(*):[31000-32000]) on slave 20140815-183925-2759502016-53897-5879-0 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.789491  5905 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-0 for 5secs
> I0815 18:39:25.782156  5908 log.cpp:699] Attempting to truncate the log to 3
> I0815 18:39:25.791250  5905 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0815 18:39:25.791558  5905 replica.cpp:508] Replica received write request for position 4
> I0815 18:39:25.791733  5905 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 33092ns
> I0815 18:39:25.791903  5905 replica.cpp:676] Persisted action at 4
> I0815 18:39:25.792234  5905 replica.cpp:655] Replica received learned notice for position 4
> I0815 18:39:25.792399  5905 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 25904ns
> I0815 18:39:25.792618  5905 leveldb.cpp:401] Deleting ~2 keys from leveldb took 17226ns
> I0815 18:39:25.792757  5905 replica.cpp:676] Persisted action at 4
> I0815 18:39:25.792945  5905 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0815 18:39:25.793436  5903 slave.cpp:1222] Queuing task '0' for executor 0 of framework '20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:25.793678  5907 containerizer.cpp:392] Starting container '403d0d42-8caa-45b4-ae1b-7062551a7857' for executor '0' of framework '20140815-183925-2759502016-53897-5879-0000'
> I0815 18:39:25.795548  5907 launcher.cpp:137] Forked child with pid '5913' for container '403d0d42-8caa-45b4-ae1b-7062551a7857'
> I0815 18:39:25.796527  5907 containerizer.cpp:502] Fetching URIs for container '403d0d42-8caa-45b4-ae1b-7062551a7857' using command '/var/jenkins/workspace/mesos-fedora-20-gcc/src/mesos-fetcher'
> I0815 18:39:25.798959  5903 slave.cpp:543] Successfully attached file '/tmp/mesos-KqTEZx/1/slaves/20140815-183925-2759502016-53897-5879-0/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/0/runs/403d0d42-8caa-45b4-ae1b-7062551a7857'
> I0815 18:39:26.141541  5909 slave.cpp:971] Will retry registration in 224.742413ms if necessary
> I0815 18:39:26.142017  5905 master.cpp:2811] Registering slave at slave(3)@192.168.122.164:53897 (fedora-20) with id 20140815-183925-2759502016-53897-5879-1
> I0815 18:39:26.142532  5905 registrar.cpp:422] Attempting to update the 'registry'
> I0815 18:39:26.144726  5908 log.cpp:680] Attempting to append 484 bytes to the log
> I0815 18:39:26.145097  5908 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0815 18:39:26.145716  5908 replica.cpp:508] Replica received write request for position 5
> I0815 18:39:26.146095  5908 leveldb.cpp:343] Persisting action (503 bytes) to leveldb took 199168ns
> I0815 18:39:26.146275  5908 replica.cpp:676] Persisted action at 5
> I0815 18:39:26.146617  5908 replica.cpp:655] Replica received learned notice for position 5
> I0815 18:39:26.146858  5908 leveldb.cpp:343] Persisting action (505 bytes) to leveldb took 24752ns
> I0815 18:39:26.147017  5908 replica.cpp:676] Persisted action at 5
> I0815 18:39:26.147223  5908 replica.cpp:661] Replica learned APPEND action at position 5
> I0815 18:39:26.147640  5908 log.cpp:699] Attempting to truncate the log to 5
> I0815 18:39:26.147938  5910 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0815 18:39:26.148450  5910 replica.cpp:508] Replica received write request for position 6
> I0815 18:39:26.148721  5910 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 34334ns
> I0815 18:39:26.148983  5910 replica.cpp:676] Persisted action at 6
> I0815 18:39:26.149394  5910 replica.cpp:655] Replica received learned notice for position 6
> I0815 18:39:26.149662  5910 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 25524ns
> I0815 18:39:26.149871  5910 leveldb.cpp:401] Deleting ~2 keys from leveldb took 22276ns
> I0815 18:39:26.150094  5910 replica.cpp:676] Persisted action at 6
> I0815 18:39:26.150271  5910 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0815 18:39:26.150953  5905 registrar.cpp:479] Successfully updated 'registry'
> I0815 18:39:26.151370  5905 master.cpp:2851] Registered slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:26.151605  5905 master.cpp:4085] Adding slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:26.152077  5908 slave.cpp:754] Registered with master master@192.168.122.164:53897; given slave ID 20140815-183925-2759502016-53897-5879-1
> I0815 18:39:26.152562  5908 slave.cpp:767] Checkpointing SlaveInfo to '/tmp/mesos-KqTEZx/2/meta/slaves/20140815-183925-2759502016-53897-5879-1/slave.info'
> I0815 18:39:26.152969  5904 slave.cpp:2324] Received ping from slave-observer(2)@192.168.122.164:53897
> I0815 18:39:26.153369  5906 hierarchical_allocator_process.hpp:442] Added slave 20140815-183925-2759502016-53897-5879-1 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] available)
> I0815 18:39:26.153872  5906 hierarchical_allocator_process.hpp:728] Offering cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-1 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.154124  5906 hierarchical_allocator_process.hpp:673] Performed allocation for slave 20140815-183925-2759502016-53897-5879-1 in 444197ns
> I0815 18:39:26.154410  5905 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-1 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:26.154686  5905 master.cpp:3559] Sending 1 offers to framework 20140815-183925-2759502016-53897-5879-0000
> .Starting task 1 on fedora-20
> I0815 18:39:26.155388  5910 sched.cpp:546] Scheduler::resourceOffers took 364580ns
> I0815 18:39:26.155798  5905 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-1 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:26.155982  5905 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-1 ] on slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.156250  5905 master.cpp:2252] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
> I0815 18:39:26.156817  5905 master.hpp:829] Adding task 1 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:26.156993  5905 master.cpp:2318] Launching task 1 of framework 20140815-183925-2759502016-53897-5879-0000 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:26.157423  5907 slave.cpp:1002] Got assigned task 1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.157959  5907 slave.cpp:1112] Launching task 1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.159862  5907 slave.cpp:1222] Queuing task '1' for executor 1 of framework '20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.160372  5906 containerizer.cpp:392] Starting container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' for executor '1' of framework '20140815-183925-2759502016-53897-5879-0000'
> I0815 18:39:26.162485  5906 launcher.cpp:137] Forked child with pid '5943' for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148'
> I0815 18:39:26.163236  5907 slave.cpp:543] Successfully attached file '/tmp/mesos-KqTEZx/2/slaves/20140815-183925-2759502016-53897-5879-1/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/1/runs/b9cd20e7-924c-4f2a-9f24-79aa12c14148'
> I0815 18:39:26.163734  5906 containerizer.cpp:502] Fetching URIs for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' using command '/var/jenkins/workspace/mesos-fedora-20-gcc/src/mesos-fetcher'
> I0815 18:39:26.165565  5904 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):752; ports(*):[31000-32000]) on slave 20140815-183925-2759502016-53897-5879-1 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.165834  5904 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-1 for 5secs
> I0815 18:39:26.209702  5908 slave.cpp:971] Will retry registration in 806.861086ms if necessary
> I0815 18:39:26.211272  5907 master.cpp:2811] Registering slave at slave(1)@192.168.122.164:53897 (fedora-20) with id 20140815-183925-2759502016-53897-5879-2
> I0815 18:39:26.211814  5907 registrar.cpp:422] Attempting to update the 'registry'
> I0815 18:39:26.214673  5904 log.cpp:680] Attempting to append 658 bytes to the log
> I0815 18:39:26.215240  5909 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
> I0815 18:39:26.216626  5909 replica.cpp:508] Replica received write request for position 7
> I0815 18:39:26.217069  5909 leveldb.cpp:343] Persisting action (677 bytes) to leveldb took 219263ns
> I0815 18:39:26.217304  5909 replica.cpp:676] Persisted action at 7
> I0815 18:39:26.217838  5909 replica.cpp:655] Replica received learned notice for position 7
> I0815 18:39:26.218969  5909 leveldb.cpp:343] Persisting action (679 bytes) to leveldb took 58237ns
> I0815 18:39:26.219197  5909 replica.cpp:676] Persisted action at 7
> I0815 18:39:26.219513  5909 replica.cpp:661] Replica learned APPEND action at position 7
> I0815 18:39:26.219944  5909 log.cpp:699] Attempting to truncate the log to 7
> I0815 18:39:26.220316  5904 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
> I0815 18:39:26.220937  5904 replica.cpp:508] Replica received write request for position 8
> I0815 18:39:26.221303  5904 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 34257ns
> I0815 18:39:26.221546  5904 replica.cpp:676] Persisted action at 8
> I0815 18:39:26.222079  5904 replica.cpp:655] Replica received learned notice for position 8
> I0815 18:39:26.222532  5904 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 20271ns
> I0815 18:39:26.223235  5904 leveldb.cpp:401] Deleting ~2 keys from leveldb took 22506ns
> I0815 18:39:26.223536  5904 replica.cpp:676] Persisted action at 8
> I0815 18:39:26.223816  5904 replica.cpp:661] Replica learned TRUNCATE action at position 8
> I0815 18:39:26.224637  5907 registrar.cpp:479] Successfully updated 'registry'
> I0815 18:39:26.225353  5907 master.cpp:2851] Registered slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:26.227272  5907 master.cpp:4085] Adding slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000]
> I0815 18:39:26.227768  5909 slave.cpp:754] Registered with master master@192.168.122.164:53897; given slave ID 20140815-183925-2759502016-53897-5879-2
> I0815 18:39:26.228679  5909 slave.cpp:767] Checkpointing SlaveInfo to '/tmp/mesos-KqTEZx/0/meta/slaves/20140815-183925-2759502016-53897-5879-2/slave.info'
> I0815 18:39:26.229449  5910 slave.cpp:2324] Received ping from slave-observer(3)@192.168.122.164:53897
> I0815 18:39:26.229959  5905 hierarchical_allocator_process.hpp:442] Added slave 20140815-183925-2759502016-53897-5879-2 (fedora-20) with cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] (and cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] available)
> I0815 18:39:26.231256  5905 hierarchical_allocator_process.hpp:728] Offering cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-2 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.231663  5905 hierarchical_allocator_process.hpp:673] Performed allocation for slave 20140815-183925-2759502016-53897-5879-2 in 447209ns
> I0815 18:39:26.231932  5907 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-2 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:26.232110  5907 master.cpp:3559] Sending 1 offers to framework 20140815-183925-2759502016-53897-5879-0000
> .Starting task 2 on fedora-20
> I0815 18:39:26.232888  5908 sched.cpp:546] Scheduler::resourceOffers took 381287ns
> I0815 18:39:26.233388  5907 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-2 with resources cpus(*):1; mem(*):1986; disk(*):752; ports(*):[31000-32000] on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:26.234263  5907 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-2 ] on slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.234570  5907 master.cpp:2252] Authorizing framework principal 'test-principal' to launch task 2 as user 'jenkins'
> I0815 18:39:26.235158  5907 master.hpp:829] Adding task 2 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:26.237426  5907 master.cpp:2318] Launching task 2 of framework 20140815-183925-2759502016-53897-5879-0000 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:26.237956  5910 slave.cpp:1002] Got assigned task 2 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.238497  5910 slave.cpp:1112] Launching task 2 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.242629  5904 containerizer.cpp:392] Starting container '4294720c-8ab1-4609-975a-1e73c8cda864' for executor '2' of framework '20140815-183925-2759502016-53897-5879-0000'
> I0815 18:39:26.248821  5904 launcher.cpp:137] Forked child with pid '5963' for container '4294720c-8ab1-4609-975a-1e73c8cda864'
> I0815 18:39:26.249713  5910 slave.cpp:1222] Queuing task '2' for executor 2 of framework '20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.250368  5910 slave.cpp:543] Successfully attached file '/tmp/mesos-KqTEZx/0/slaves/20140815-183925-2759502016-53897-5879-2/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/2/runs/4294720c-8ab1-4609-975a-1e73c8cda864'
> I0815 18:39:26.250810  5904 containerizer.cpp:502] Fetching URIs for container '4294720c-8ab1-4609-975a-1e73c8cda864' using command '/var/jenkins/workspace/mesos-fedora-20-gcc/src/mesos-fetcher'
> I0815 18:39:26.252467  5905 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):752; ports(*):[31000-32000]) on slave 20140815-183925-2759502016-53897-5879-2 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:26.253209  5905 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-2 for 5secs
> I0815 18:39:26.636766  5903 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 114821ns
> I0815 18:39:26.804400  5905 slave.cpp:2535] Monitoring executor '0' of framework '20140815-183925-2759502016-53897-5879-0000' in container '403d0d42-8caa-45b4-ae1b-7062551a7857'
> I0815 18:39:26.818725  5905 slave.cpp:2535] Monitoring executor '1' of framework '20140815-183925-2759502016-53897-5879-0000' in container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148'
> I0815 18:39:26.837345  5910 slave.cpp:2535] Monitoring executor '2' of framework '20140815-183925-2759502016-53897-5879-0000' in container '4294720c-8ab1-4609-975a-1e73c8cda864'
> I0815 18:39:27.637380  5910 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 97086ns
> I0815 18:39:27.850338  5910 monitor.cpp:140] Failed to collect resource usage for container '403d0d42-8caa-45b4-ae1b-7062551a7857' for executor '0' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 403d0d42-8caa-45b4-ae1b-7062551a7857
> I0815 18:39:27.850409  5910 monitor.cpp:140] Failed to collect resource usage for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' for executor '1' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: b9cd20e7-924c-4f2a-9f24-79aa12c14148
> I0815 18:39:28.706199  5910 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 112286ns
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:28.844923  5963 process.cpp:1770] libprocess is initialized on 192.168.122.164:56895 for 8 cpus
> I0815 18:39:28.847806  5963 logging.cpp:172] Logging to STDERR
> I0815 18:39:28.849983  5963 exec.cpp:132] Version: 0.20.0
> I0815 18:39:28.850622  6057 exec.cpp:182] Executor started at: executor(1)@192.168.122.164:56895 with pid 5963
> I0815 18:39:28.851927  5910 monitor.cpp:140] Failed to collect resource usage for container '403d0d42-8caa-45b4-ae1b-7062551a7857' for executor '0' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 403d0d42-8caa-45b4-ae1b-7062551a7857
> I0815 18:39:28.851963  5910 monitor.cpp:140] Failed to collect resource usage for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' for executor '1' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: b9cd20e7-924c-4f2a-9f24-79aa12c14148
> I0815 18:39:28.855018  5910 slave.cpp:1733] Got registration for executor '2' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.855439  5910 slave.cpp:1852] Flushing queued task 2 for executor '2' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.856442  6062 exec.cpp:206] Executor registered on slave 20140815-183925-2759502016-53897-5879-2
> IRegistered executor on fedora-20
> 0815 18:39:28.857527  6062 exec.cpp:218] Executor::registered took 79415ns
> I0815 18:39:28.858777  6062 exec.cpp:293] Executor asked to run task '2'
> I0815 18:39:28.859367  6062 exec.cpp:302] Executor::launchTask took 31952ns
> Starting task 2
> sh -c 'echo hello'
> hello
> Forked command at 6065
> I0815 18:39:28.867358  6057 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.868110  5905 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:56895
> I0815 18:39:28.868278  5905 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.868305  5905 status_update_manager.cpp:499] Creating StatusUpdate stream for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.868415  5905 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:28.868556  5905 master.cpp:3180] Forwarding status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.868610  5905 master.cpp:3146] Status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:28.868641  5905 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.868659  5905 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:56895
> Task 2 is in state 1
> I0815 18:39:28.868892  5905 sched.cpp:637] Scheduler::statusUpdate took 19585ns
> I0815 18:39:28.868944  5905 master.cpp:2661] Forwarding status update acknowledgement 04df0748-9d36-4509-8bf9-9f07739692ba for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:28.869017  5905 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.869060  5905 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 04df0748-9d36-4509-8bf9-9f07739692ba) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.869668  6061 exec.cpp:339] Executor received status update acknowledgement 04df0748-9d36-4509-8bf9-9f07739692ba for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:28.952711  5913 process.cpp:1770] libprocess is initialized on 192.168.122.164:41301 for 8 cpus
> I0815 18:39:28.960372  5913 logging.cpp:172] Logging to STDERR
> I0815 18:39:28.962918  5913 exec.cpp:132] Version: 0.20.0
> I0815 18:39:28.963690  6075 exec.cpp:182] Executor started at: executor(1)@192.168.122.164:41301 with pid 5913
> I0815 18:39:28.964756  5905 slave.cpp:1733] Got registration for executor '0' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.965435  5905 slave.cpp:1852] Flushing queued task 0 for executor '0' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.970010  6071 exec.cpp:206] Executor registered on slave 20140815-183925-2759502016-53897-5879-0
> Registered executor on fedora-20
> I0815 18:39:28.971237  6071 exec.cpp:218] Executor::registered took 116524ns
> I0815 18:39:28.976485  6075 exec.cpp:293] Executor asked to run task '0'
> I0815 18:39:28.977442  6075 exec.cpp:302] Executor::launchTask took 116732ns
> Starting task 0
> sh -c 'echo hello'
> hello
> Forked command at 6077
> I0815 18:39:28.985376  6075 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986026  5910 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:41301
> I0815 18:39:28.986114  5910 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986129  5910 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986228  5910 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:28.986325  5910 master.cpp:3180] Forwarding status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986394  5910 master.cpp:3146] Status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:28.986426  5910 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986435  5910 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:41301
> Task 0 is in state 1
> I0815 18:39:28.986660  5910 sched.cpp:637] Scheduler::statusUpdate took 10588ns
> I0815 18:39:28.986701  5910 master.cpp:2661] Forwarding status update acknowledgement ce02b414-9583-4d61-8f03-9da7a0ae9c00 for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:28.986747  5910 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.986783  5910 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: ce02b414-9583-4d61-8f03-9da7a0ae9c00) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:28.987440  6073 exec.cpp:339] Executor received status update acknowledgement ce02b414-9583-4d61-8f03-9da7a0ae9c00 for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:29.153564  5943 process.cpp:1770] libprocess is initialized on 192.168.122.164:33533 for 8 cpus
> I0815 18:39:29.154485  5943 logging.cpp:172] Logging to STDERR
> I0815 18:39:29.157604  5943 exec.cpp:132] Version: 0.20.0
> I0815 18:39:29.158229  6085 exec.cpp:182] Executor started at: executor(1)@192.168.122.164:33533 with pid 5943
> I0815 18:39:29.159142  5910 slave.cpp:1733] Got registration for executor '1' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.159499  5910 slave.cpp:1852] Flushing queued task 1 for executor '1' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.160441  6085 exec.cpp:206] Executor registered on slave 20140815-183925-2759502016-53897-5879-1
> IRegistered executor on fedora-20
> 0815 18:39:29.161651  6085 exec.cpp:218] Executor::registered took 78294ns
> I0815 18:39:29.162453  6080 exec.cpp:293] Executor asked to run task '1'
> IStarting task 1
> 0815 18:39:29.162781  6080 exec.cpp:302] Executor::launchTask took 65494ns
> sh -c 'echo hello'
> hello
> Forked command at 6089
> I0815 18:39:29.171131  6084 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.171828  5903 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:33533
> I0815 18:39:29.171932  5903 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.171948  5903 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.172006  5903 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:29.172103  5903 master.cpp:3180] Forwarding status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.172138  5903 master.cpp:3146] Status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:29.172188  5903 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.172207  5903 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:33533
> Task 1 is in state 1
> I0815 18:39:29.172426  5903 sched.cpp:637] Scheduler::statusUpdate took 10098ns
> I0815 18:39:29.172467  5903 master.cpp:2661] Forwarding status update acknowledgement ad3b2389-ffb0-40c0-a1c1-2a3920fecc30 for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:29.172514  5903 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.172569  5903 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: ad3b2389-ffb0-40c0-a1c1-2a3920fecc30) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.173239  6087 exec.cpp:339] Executor received status update acknowledgement ad3b2389-ffb0-40c0-a1c1-2a3920fecc30 for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.706584  5903 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 82005ns
> I0815 18:39:29.852252  5905 monitor.cpp:140] Failed to collect resource usage for container '403d0d42-8caa-45b4-ae1b-7062551a7857' for executor '0' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 403d0d42-8caa-45b4-ae1b-7062551a7857
> I0815 18:39:29.852437  5905 monitor.cpp:140] Failed to collect resource usage for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' for executor '1' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: b9cd20e7-924c-4f2a-9f24-79aa12c14148
> Command exited with status 0 (pid: 6065)
> I0815 18:39:29.869328  6063 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.869802  5909 slave.cpp:2087] Handling status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:56895
> I0815 18:39:29.869979  5909 slave.cpp:3897] Terminating task 2
> I0815 18:39:29.870471  5909 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.870651  5909 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:29.870925  5909 master.cpp:3180] Forwarding status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.871242  5909 master.cpp:3146] Status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> Task 2 is in state 2
> I0815 18:39:29.871673  5909 master.hpp:847] Removing task 2 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:29.871927  5909 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-2 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.872099  5909 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-2 for 5secs
> I0815 18:39:29.871109  5907 slave.cpp:2245] Status update manager successfully handled status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.872480  5907 slave.cpp:2251] Sending acknowledgement for status update TASK_FINISHED (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:56895
> I0815 18:39:29.871577  5910 sched.cpp:637] Scheduler::statusUpdate took 153364ns
> I0815 18:39:29.873021  5910 master.cpp:2661] Forwarding status update acknowledgement 6f27d42f-fd90-498b-99a6-26104847e35a for task 2 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:29.873257  5907 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.873571  6060 exec.cpp:339] Executor received status update acknowledgement 6f27d42f-fd90-498b-99a6-26104847e35a for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.878247  5907 status_update_manager.cpp:530] Cleaning up status update stream for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.878669  5907 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 6f27d42f-fd90-498b-99a6-26104847e35a) for task 2 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:29.878928  5907 slave.cpp:3939] Completing task 2
> I0815 18:39:29.954953  5830 exec.cpp:86] Committing suicide by killing the process group
> I0815 18:39:30.019932  5795 exec.cpp:86] Committing suicide by killing the process group
> Command exited with status 0 (pid: 6077)
> I0815 18:39:30.022280  6068 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.022769  5841 exec.cpp:86] Committing suicide by killing the process group
> I0815 18:39:30.030586  5906 slave.cpp:2087] Handling status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:41301
> I0815 18:39:30.030618  5906 slave.cpp:3897] Terminating task 0
> I0815 18:39:30.042686  5908 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.042716  5908 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:30.042791  5908 master.cpp:3180] Forwarding status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.042825  5908 master.cpp:3146] Status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.042857  5908 master.hpp:847] Removing task 0 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:30.042901  5908 slave.cpp:2245] Status update manager successfully handled status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.042913  5908 slave.cpp:2251] Sending acknowledgement for status update TASK_FINISHED (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:41301
> Task 0 is in state 2
> I0815 18:39:30.043218  5908 sched.cpp:637] Scheduler::statusUpdate took 59420ns
> I0815 18:39:30.043279  5908 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-0 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.043304  5908 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-0 for 5secs
> I0815 18:39:30.043339  5908 master.cpp:2661] Forwarding status update acknowledgement ae0835de-419d-44e7-8d16-69d8d0075dd3 for task 0 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.043385  5908 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.043404  5908 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.043450  5908 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: ae0835de-419d-44e7-8d16-69d8d0075dd3) for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.043463  5908 slave.cpp:3939] Completing task 0
> I0815 18:39:30.054128  6071 exec.cpp:339] Executor received status update acknowledgement ae0835de-419d-44e7-8d16-69d8d0075dd3 for task 0 of framework 20140815-183925-2759502016-53897-5879-0000
> Command exited with status 0 (pid: 6089)
> I0815 18:39:30.171659  6082 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.171906  5906 slave.cpp:2087] Handling status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:33533
> I0815 18:39:30.171936  5906 slave.cpp:3897] Terminating task 1
> I0815 18:39:30.172114  5906 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.172138  5906 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:30.172253  5906 master.cpp:3180] Forwarding status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.172289  5906 master.cpp:3146] Status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.172319  5906 master.hpp:847] Removing task 1 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:30.172365  5906 slave.cpp:2245] Status update manager successfully handled status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.172376  5906 slave.cpp:2251] Sending acknowledgement for status update TASK_FINISHED (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:33533
> Task 1 is in state 2
> I0815 18:39:30.224622  5908 sched.cpp:637] Scheduler::statusUpdate took 493883ns
> I0815 18:39:30.225030  5908 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-1 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.225472  5908 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-1 for 5secs
> I0815 18:39:30.225901  5908 master.cpp:2661] Forwarding status update acknowledgement a01d9509-e7a2-4cde-8b72-2a7c5bff3a02 for task 1 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.226629  6082 exec.cpp:339] Executor received status update acknowledgement a01d9509-e7a2-4cde-8b72-2a7c5bff3a02 for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.227445  5903 status_update_manager.cpp:398] Received status update acknowledgement (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.227751  5903 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.228262  5906 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: a01d9509-e7a2-4cde-8b72-2a7c5bff3a02) for task 1 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.228742  5906 slave.cpp:3939] Completing task 1
> I0815 18:39:30.637192  5910 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0815 18:39:30.707772  5905 hierarchical_allocator_process.hpp:728] Offering mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.708274  5905 hierarchical_allocator_process.hpp:728] Offering mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.708523  5905 hierarchical_allocator_process.hpp:728] Offering mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-0 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.708798  5905 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 1.146469ms
> I0815 18:39:30.709027  5907 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-3 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:30.709332  5907 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-4 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:30.709560  5907 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-5 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:30.709729  5907 master.cpp:3559] Sending 3 offers to framework 20140815-183925-2759502016-53897-5879-0000
> .Starting task 3 on fedora-20
> Starting task 4 on fedora-20
> I0815 18:39:30.710588  5907 sched.cpp:546] Scheduler::resourceOffers took 532450ns
> I0815 18:39:30.711072  5907 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-3 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:30.711324  5907 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-3 ] on slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.711478  5907 master.cpp:2252] Authorizing framework principal 'test-principal' to launch task 3 as user 'jenkins'
> I0815 18:39:30.711956  5907 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-4 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:30.712235  5907 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-4 ] on slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.712373  5907 master.cpp:2252] Authorizing framework principal 'test-principal' to launch task 4 as user 'jenkins'
> I0815 18:39:30.712637  5907 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-5 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:30.712935  5907 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-5 ] on slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.713155  5907 master.hpp:829] Adding task 3 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:30.713335  5907 master.cpp:2318] Launching task 3 of framework 20140815-183925-2759502016-53897-5879-0000 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.713567  5904 slave.cpp:1002] Got assigned task 3 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.714563  5904 slave.cpp:1112] Launching task 3 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.716039  5910 containerizer.cpp:392] Starting container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' for executor '3' of framework '20140815-183925-2759502016-53897-5879-0000'
> I0815 18:39:30.717670  5910 launcher.cpp:137] Forked child with pid '6095' for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0'
> I0815 18:39:30.718803  5910 containerizer.cpp:502] Fetching URIs for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' using command '/var/jenkins/workspace/mesos-fedora-20-gcc/src/mesos-fetcher'
> I0815 18:39:30.718293  5904 slave.cpp:1222] Queuing task '3' for executor 3 of framework '20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.720482  5904 slave.cpp:543] Successfully attached file '/tmp/mesos-KqTEZx/1/slaves/20140815-183925-2759502016-53897-5879-0/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/3/runs/2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0'
> I0815 18:39:30.721103  5907 master.hpp:829] Adding task 4 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:30.721487  5907 master.cpp:2318] Launching task 4 of framework 20140815-183925-2759502016-53897-5879-0000 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:30.721422  5904 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):752; ports(*):[31000-32000]) on slave 20140815-183925-2759502016-53897-5879-0 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.721866  5904 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-0 for 5secs
> I0815 18:39:30.722144  5904 slave.cpp:1002] Got assigned task 4 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.722476  5904 slave.cpp:1112] Launching task 4 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.723285  5905 hierarchical_allocator_process.hpp:563] Recovered mem(*):1954; disk(*):752; ports(*):[31000-32000] (total allocatable: mem(*):1954; disk(*):752; ports(*):[31000-32000]) on slave 20140815-183925-2759502016-53897-5879-2 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.723453  5905 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-2 for 5secs
> I0815 18:39:30.724890  5903 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-1 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:30.725078  5903 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-1 for 5secs
> I0815 18:39:30.732270  5903 containerizer.cpp:392] Starting container '51624981-9826-4f78-9cb0-1e02b33607b7' for executor '4' of framework '20140815-183925-2759502016-53897-5879-0000'
> I0815 18:39:30.734537  5903 launcher.cpp:137] Forked child with pid '6101' for container '51624981-9826-4f78-9cb0-1e02b33607b7'
> I0815 18:39:30.739393  5903 containerizer.cpp:502] Fetching URIs for container '51624981-9826-4f78-9cb0-1e02b33607b7' using command '/var/jenkins/workspace/mesos-fedora-20-gcc/src/mesos-fetcher'
> I0815 18:39:32.008893  5905 hierarchical_allocator_process.hpp:810] Filtered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:33.043537  5908 containerizer.cpp:990] Executor for container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148' has exited
> I0815 18:39:33.045368  5908 containerizer.cpp:874] Destroying container 'b9cd20e7-924c-4f2a-9f24-79aa12c14148'
> I0815 18:39:33.058595  5909 slave.cpp:2593] Executor '1' of framework 20140815-183925-2759502016-53897-5879-0000 exited with status 0
> I0815 18:39:33.058724  5909 slave.cpp:2729] Cleaning up executor '1' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:33.058961  5909 slave.cpp:2804] Cleaning up framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:33.059187  5909 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/2/slaves/20140815-183925-2759502016-53897-5879-1/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/1/runs/b9cd20e7-924c-4f2a-9f24-79aa12c14148' for gc 6.99999931899259days in the future
> I0815 18:39:33.059305  5909 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/2/slaves/20140815-183925-2759502016-53897-5879-1/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/1' for gc 6.99999931814815days in the future
> I0815 18:39:33.059330  5909 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/2/slaves/20140815-183925-2759502016-53897-5879-1/frameworks/20140815-183925-2759502016-53897-5879-0000' for gc 6.99999931683852days in the future
> I0815 18:39:33.059382  5909 status_update_manager.cpp:282] Closing status update streams for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:33.059697  5905 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 1.050915208secs
> I0815 18:39:33.061429  5904 slave.cpp:1222] Queuing task '4' for executor 4 of framework '20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:33.061509  5904 slave.cpp:543] Successfully attached file '/tmp/mesos-KqTEZx/0/slaves/20140815-183925-2759502016-53897-5879-2/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/4/runs/51624981-9826-4f78-9cb0-1e02b33607b7'
> I0815 18:39:33.079547  5903 monitor.cpp:140] Failed to collect resource usage for container '403d0d42-8caa-45b4-ae1b-7062551a7857' for executor '0' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 403d0d42-8caa-45b4-ae1b-7062551a7857
> I0815 18:39:34.045624  5905 containerizer.cpp:990] Executor for container '403d0d42-8caa-45b4-ae1b-7062551a7857' has exited
> I0815 18:39:34.045685  5905 containerizer.cpp:874] Destroying container '403d0d42-8caa-45b4-ae1b-7062551a7857'
> I0815 18:39:34.056360  5905 containerizer.cpp:990] Executor for container '4294720c-8ab1-4609-975a-1e73c8cda864' has exited
> I0815 18:39:34.056385  5905 containerizer.cpp:874] Destroying container '4294720c-8ab1-4609-975a-1e73c8cda864'
> I0815 18:39:34.066722  5909 hierarchical_allocator_process.hpp:810] Filtered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:34.066834  5909 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 313648ns
> I0815 18:39:34.071020  5909 slave.cpp:2535] Monitoring executor '3' of framework '20140815-183925-2759502016-53897-5879-0000' in container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0'
> I0815 18:39:34.074368  5903 slave.cpp:2535] Monitoring executor '4' of framework '20140815-183925-2759502016-53897-5879-0000' in container '51624981-9826-4f78-9cb0-1e02b33607b7'
> I0815 18:39:34.074650  5903 slave.cpp:2593] Executor '2' of framework 20140815-183925-2759502016-53897-5879-0000 exited with status 0
> I0815 18:39:34.074681  5903 slave.cpp:2729] Cleaning up executor '2' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:34.074774  5903 slave.cpp:2593] Executor '0' of framework 20140815-183925-2759502016-53897-5879-0000 exited with status 0
> I0815 18:39:34.074796  5903 slave.cpp:2729] Cleaning up executor '0' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:34.074909  5903 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/0/slaves/20140815-183925-2759502016-53897-5879-2/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/2/runs/4294720c-8ab1-4609-975a-1e73c8cda864' for gc 6.99999913514963days in the future
> I0815 18:39:34.074944  5903 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/0/slaves/20140815-183925-2759502016-53897-5879-2/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/2' for gc 6.99999913479111days in the future
> I0815 18:39:34.074969  5903 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/1/slaves/20140815-183925-2759502016-53897-5879-0/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/0/runs/403d0d42-8caa-45b4-ae1b-7062551a7857' for gc 6.99999913393482days in the future
> I0815 18:39:34.074990  5903 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/1/slaves/20140815-183925-2759502016-53897-5879-0/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/0' for gc 6.9999991336days in the future
> I0815 18:39:35.534659  5903 hierarchical_allocator_process.hpp:810] Filtered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:35.534936  5903 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 435855ns
> I0815 18:39:35.535315  5903 monitor.cpp:140] Failed to collect resource usage for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' for executor '3' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:35.576807  6101 process.cpp:1770] libprocess is initialized on 192.168.122.164:46967 for 8 cpus
> I0815 18:39:35.577446  6101 logging.cpp:172] Logging to STDERR
> I0815 18:39:35.578342  6101 exec.cpp:132] Version: 0.20.0
> I0815 18:39:35.580663  6194 exec.cpp:182] Executor started at: executor(1)@192.168.122.164:46967 with pid 6101
> I0815 18:39:35.581887  5903 slave.cpp:1733] Got registration for executor '4' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:35.582291  5903 slave.cpp:1852] Flushing queued task 4 for executor '4' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:35.583292  6194 exec.cpp:206] Executor registered on slave 20140815-183925-2759502016-53897-5879-2
> I0815 18:39:35.584350  6194 exec.cpp:218] Executor::registered took 67604ns
> Registered executor on fedora-20
> I0815 18:39:35.585106  6190 exec.cpp:293] Executor asked to run task '4'
> I0815 18:39:35.585435  6190 exec.cpp:302] Executor::launchTask took 36829ns
> Starting task 4
> sh -c 'echo hello'
> hello
> Forked command at 6197
> I0815 18:39:35.590051  6190 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:35.637886  5903 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0815 18:39:36.247509  5903 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:46967
> I0815 18:39:36.247647  5903 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.247661  5903 status_update_manager.cpp:499] Creating StatusUpdate stream for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.247723  5903 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:36.247903  5903 master.cpp:3180] Forwarding status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.247951  5903 master.cpp:3146] Status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:36.247985  5903 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.247995  5903 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:46967
> Task 4 is in state 1
> I0815 18:39:36.350466  5909 sched.cpp:637] Scheduler::statusUpdate took 148123ns
> I0815 18:39:36.350689  5909 master.cpp:2661] Forwarding status update acknowledgement 2d15db30-6956-4a00-a933-6eb61a2582f5 for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:36.351254  6192 exec.cpp:339] Executor received status update acknowledgement 2d15db30-6956-4a00-a933-6eb61a2582f5 for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.456665  5905 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.457010  5903 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 2d15db30-6956-4a00-a933-6eb61a2582f5) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0815 18:39:36.471570  6095 process.cpp:1770] libprocess is initialized on 192.168.122.164:51714 for 8 cpus
> I0815 18:39:36.472519  6095 logging.cpp:172] Logging to STDERR
> I0815 18:39:36.475363  6095 exec.cpp:132] Version: 0.20.0
> I0815 18:39:36.475847  6205 exec.cpp:182] Executor started at: executor(1)@192.168.122.164:51714 with pid 6095
> I0815 18:39:36.476696  5909 slave.cpp:1733] Got registration for executor '3' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.478678  5909 slave.cpp:1852] Flushing queued task 3 for executor '3' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.479542  6202 exec.cpp:206] Executor registered on slave 20140815-183925-2759502016-53897-5879-0
> Registered executor on fedora-20
> I0815 18:39:36.481144  6202 exec.cpp:218] Executor::registered took 446768ns
> I0815 18:39:36.487547  6199 exec.cpp:293] Executor asked to run task '3'
> Starting task 3
> I0815 18:39:36.488740  6199 exec.cpp:302] Executor::launchTask took 68775ns
> sh -c 'echo hello'
> hello
> Forked command at 6207
> I0815 18:39:36.494590  6200 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.495369  5906 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:51714
> I0815 18:39:36.495472  5906 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.495486  5906 status_update_manager.cpp:499] Creating StatusUpdate stream for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.495545  5906 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:36.495632  5906 master.cpp:3180] Forwarding status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.495666  5906 master.cpp:3146] Status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:36.495687  5906 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.495697  5906 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:51714
> Task 3 is in state 1
> I0815 18:39:36.495960  5906 sched.cpp:637] Scheduler::statusUpdate took 12625ns
> I0815 18:39:36.496022  5906 master.cpp:2661] Forwarding status update acknowledgement 3084464e-f95d-451d-9a1c-464ac3e64c6f for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:36.496090  5906 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.496151  5906 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 3084464e-f95d-451d-9a1c-464ac3e64c6f) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.497086  6200 exec.cpp:339] Executor received status update acknowledgement 3084464e-f95d-451d-9a1c-464ac3e64c6f for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.536113  5907 hierarchical_allocator_process.hpp:728] Offering mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.536325  5907 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 353417ns
> I0815 18:39:36.536428  5907 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-6 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:36.536480  5907 master.cpp:3559] Sending 1 offers to framework 20140815-183925-2759502016-53897-5879-0000
> .I0815 18:39:36.536638  5907 sched.cpp:546] Scheduler::resourceOffers took 22395ns
> I0815 18:39:36.536689  5907 monitor.cpp:140] Failed to collect resource usage for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' for executor '3' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0
> I0815 18:39:36.536770  5907 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-6 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 (fedora-20)
> I0815 18:39:36.536818  5907 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-6 ] on slave 20140815-183925-2759502016-53897-5879-1 at slave(3)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.536945  5907 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-1 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.536972  5907 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-1 for 5secs
> Command exited with status 0 (pid: 6197)
> I0815 18:39:36.590775  6190 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.591614  5908 slave.cpp:2087] Handling status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 from executor(1)@192.168.122.164:46967
> I0815 18:39:36.591819  5908 slave.cpp:3897] Terminating task 4
> I0815 18:39:36.598320  5910 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.599001  5910 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:36.599330  5910 master.cpp:3180] Forwarding status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.599652  5910 master.cpp:3146] Status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> Task 4 is in state 2
> I0815 18:39:36.599531  5903 slave.cpp:2245] Status update manager successfully handled status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.600414  5903 slave.cpp:2251] Sending acknowledgement for status update TASK_FINISHED (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to executor(1)@192.168.122.164:46967
> I0815 18:39:36.600074  5908 sched.cpp:637] Scheduler::statusUpdate took 177097ns
> I0815 18:39:36.601402  6195 exec.cpp:339] Executor received status update acknowledgement 65bfb7ab-b203-47fa-bc47-66557481b4ec for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.606214  5910 master.hpp:847] Removing task 4 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:36.606827  5910 master.cpp:2661] Forwarding status update acknowledgement 65bfb7ab-b203-47fa-bc47-66557481b4ec for task 4 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:36.607453  5910 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.607666  5910 status_update_manager.cpp:530] Cleaning up status update stream for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.607970  5910 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 65bfb7ab-b203-47fa-bc47-66557481b4ec) for task 4 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.607333  5906 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-2 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:36.608373  5906 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-2 for 5secs
> I0815 18:39:36.608608  5910 slave.cpp:3939] Completing task 4
> Command exited with status 0 (pid: 6207)
> I0815 18:39:37.495481  6198 exec.cpp:525] Executor sending status update TASK_FINISHED (UUID: 9edb349e-2440-400f-86e0-33a050d897f7) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.202934  5909 hierarchical_allocator_process.hpp:728] Offering mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.203074  5909 hierarchical_allocator_process.hpp:810] Filtered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-1 for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.203112  5909 hierarchical_allocator_process.hpp:653] Performed allocation for 3 slaves in 273743ns
> I0815 18:39:39.203378  5909 master.hpp:857] Adding offer 20140815-183925-2759502016-53897-5879-7 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:39.203444  5909 master.cpp:3559] Sending 1 offers to framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.203491  5909 containerizer.cpp:990] Executor for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' has exited
> I0815 18:39:39.203505  5909 containerizer.cpp:874] Destroying container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0'
> .I0815 18:39:39.214519  5909 sched.cpp:546] Scheduler::resourceOffers took 34251ns
> I0815 18:39:39.214601  5909 monitor.cpp:140] Failed to collect resource usage for container '2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' for executor '3' of framework '20140815-183925-2759502016-53897-5879-0000': Unknown container: 2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0
> I0815 18:39:39.234707  5909 master.hpp:867] Removing offer 20140815-183925-2759502016-53897-5879-7 with resources mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 on slave 20140815-183925-2759502016-53897-5879-2 (fedora-20)
> I0815 18:39:39.234779  5909 master.cpp:2169] Processing reply for offers: [ 20140815-183925-2759502016-53897-5879-7 ] on slave 20140815-183925-2759502016-53897-5879-2 at slave(1)@192.168.122.164:53897 (fedora-20) for framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.235016  5909 hierarchical_allocator_process.hpp:563] Recovered mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-2 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.235055  5909 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-2 for 5secs
> I0815 18:39:39.235283  5909 slave.cpp:2593] Executor '3' of framework 20140815-183925-2759502016-53897-5879-0000 exited with status 0
> I0815 18:39:39.236003  5909 slave.cpp:2087] Handling status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 from @0.0.0.0:0
> I0815 18:39:39.236043  5909 slave.cpp:3897] Terminating task 3
> W0815 18:39:39.236129  5909 containerizer.cpp:780] Ignoring update for unknown container: 2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0
> I0815 18:39:39.236237  5909 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236273  5909 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 to master@192.168.122.164:53897
> I0815 18:39:39.236378  5909 master.cpp:3180] Forwarding status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236415  5909 master.cpp:3146] Status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 from slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:39.236448  5909 master.hpp:847] Removing task 3 with resources cpus(*):1; mem(*):32 on slave 20140815-183925-2759502016-53897-5879-0 (fedora-20)
> I0815 18:39:39.236492  5909 slave.cpp:2245] Status update manager successfully handled status update TASK_FAILED (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> Task 3 is in state 3
> I0815 18:39:39.236533  5909 sched.cpp:637] Scheduler::statusUpdate took 7419ns
> I0815 18:39:39.236577  5909 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):32 (total allocatable: mem(*):1986; disk(*):752; ports(*):[31000-32000]; cpus(*):1) on slave 20140815-183925-2759502016-53897-5879-0 from framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236614  5909 hierarchical_allocator_process.hpp:594] Framework 20140815-183925-2759502016-53897-5879-0000 filtered slave 20140815-183925-2759502016-53897-5879-0 for 5secs
> I0815 18:39:39.236650  5909 master.cpp:2661] Forwarding status update acknowledgement 460f849c-199f-4041-a2a3-71ab525f1d94 for task 3 of framework 20140815-183925-2759502016-53897-5879-0000 to slave 20140815-183925-2759502016-53897-5879-0 at slave(2)@192.168.122.164:53897 (fedora-20)
> I0815 18:39:39.236698  5909 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236718  5909 status_update_manager.cpp:530] Cleaning up status update stream for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236776  5909 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 460f849c-199f-4041-a2a3-71ab525f1d94) for task 3 of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236789  5909 slave.cpp:3939] Completing task 3
> I0815 18:39:39.236806  5909 slave.cpp:2729] Cleaning up executor '3' of framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236912  5909 slave.cpp:2804] Cleaning up framework 20140815-183925-2759502016-53897-5879-0000
> I0815 18:39:39.236959  5909 gc.cpp:56] Scheduling '/tmp/mesos-KqTEZx/1/slaves/20140815-183925-2759502016-53897-5879-0/frameworks/20140815-183925-2759502016-53897-5879-0000/executors/3/runs/2d3ebc9e-6fb7-4c3c-84c1-a3e81e3c2df0' for gc 6.99999725857481days in the future
> {code}



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