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

[Vinod Kone (JIRA)]

Vinod Kone created MESOS-1709:
---------------------------------

             Summary: 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


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.2#6252)