Major Description
[ RUN ] SlaveRecoveryTest/0.RemoveNonCheckpointingFramework
Using temporary directory '/tmp/SlaveRecoveryTest_0_RemoveNonCheckpointingFramework_ctBWwE'
I0514 20:45:43.750376 36778 leveldb.cpp:176] Opened db in 116.754848ms
I0514 20:45:43.766901 36778 leveldb.cpp:183] Compacted db in 16.431296ms
I0514 20:45:43.767030 36778 leveldb.cpp:198] Created db iterator in 18645ns
I0514 20:45:43.767072 36778 leveldb.cpp:204] Seeked to beginning of db in 1665ns
I0514 20:45:43.767089 36778 leveldb.cpp:273] Iterated through 0 keys in the db in 342ns
I0514 20:45:43.767129 36778 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0514 20:45:43.767776 36801 recover.cpp:425] Starting replica recovery
I0514 20:45:43.768074 36801 recover.cpp:451] Replica is in EMPTY status
I0514 20:45:43.770112 36793 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0514 20:45:43.770190 36804 master.cpp:267] Master 20140514-204543-1828659978-57356-36778 (smfd-atr-11-sr1.devel.twitter.com) started on 10.35.255.108:57356
I0514 20:45:43.770254 36804 master.cpp:304] Master only allowing authenticated frameworks to register
I0514 20:45:43.770282 36804 master.cpp:309] Master only allowing authenticated slaves to register
I0514 20:45:43.770301 36804 credentials.hpp:35] Loading credentials for authentication
W0514 20:45:43.770616 36804 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_RemoveNonCheckpointingFramework_ctBWwE/credentials': No such file or directory
I0514 20:45:43.770705 36806 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0514 20:45:43.771790 36808 recover.cpp:542] Updating replica status to STARTING
I0514 20:45:43.772866 36801 master.cpp:919] The newly elected leader is master@10.35.255.108:57356 with id 20140514-204543-1828659978-57356-36778
I0514 20:45:43.772904 36801 master.cpp:929] Elected as the leading master!
I0514 20:45:43.772924 36801 master.cpp:750] Recovering from registrar
I0514 20:45:43.773144 36802 registrar.cpp:313] Recovering registrar
I0514 20:45:43.825598 36813 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 53.288306ms
I0514 20:45:43.825683 36813 replica.cpp:320] Persisted replica status to STARTING
I0514 20:45:43.825914 36813 recover.cpp:451] Replica is in STARTING status
I0514 20:45:43.827308 36807 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0514 20:45:43.827898 36814 recover.cpp:188] Received a recover response from a replica in STARTING status
I0514 20:45:43.828277 36812 recover.cpp:542] Updating replica status to VOTING
I0514 20:45:43.842594 36810 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.148097ms
I0514 20:45:43.842643 36810 replica.cpp:320] Persisted replica status to VOTING
I0514 20:45:43.842743 36805 recover.cpp:556] Successfully joined the Paxos group
I0514 20:45:43.843027 36805 recover.cpp:440] Recover process terminated
I0514 20:45:43.843966 36797 log.cpp:656] Attempting to start the writer
I0514 20:45:43.845717 36794 replica.cpp:474] Replica received implicit promise request with proposal 1
I0514 20:45:43.850947 36794 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.159061ms
I0514 20:45:43.851055 36794 replica.cpp:342] Persisted promised to 1
I0514 20:45:43.851780 36801 coordinator.cpp:230] Coordinator attemping to fill missing position
I0514 20:45:43.853118 36800 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0514 20:45:43.859256 36800 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 6.092406ms
I0514 20:45:43.859344 36800 replica.cpp:676] Persisted action at 0
I0514 20:45:43.860616 36808 replica.cpp:508] Replica received write request for position 0
I0514 20:45:43.860724 36808 leveldb.cpp:438] Reading position from leveldb took 70475ns
I0514 20:45:43.867585 36808 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 6.825758ms
I0514 20:45:43.867629 36808 replica.cpp:676] Persisted action at 0
I0514 20:45:43.868314 36799 replica.cpp:655] Replica received learned notice for position 0
I0514 20:45:43.875905 36799 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.547621ms
I0514 20:45:43.876014 36799 replica.cpp:676] Persisted action at 0
I0514 20:45:43.876044 36799 replica.cpp:661] Replica learned NOP action at position 0
I0514 20:45:43.876915 36798 log.cpp:672] Writer started with ending position 0
I0514 20:45:43.878356 36794 leveldb.cpp:438] Reading position from leveldb took 32642ns
I0514 20:45:43.881211 36806 registrar.cpp:346] Successfully fetched the registry (0B)
I0514 20:45:43.881439 36806 registrar.cpp:422] Attempting to update the 'registry'
I0514 20:45:43.883990 36808 log.cpp:680] Attempting to append 155 bytes to the log
I0514 20:45:43.884259 36801 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0514 20:45:43.885217 36802 replica.cpp:508] Replica received write request for position 1
I0514 20:45:43.892568 36802 leveldb.cpp:343] Persisting action (174 bytes) to leveldb took 7.301141ms
I0514 20:45:43.892647 36802 replica.cpp:676] Persisted action at 1
I0514 20:45:43.893304 36798 replica.cpp:655] Replica received learned notice for position 1
I0514 20:45:43.900894 36798 leveldb.cpp:343] Persisting action (176 bytes) to leveldb took 7.549491ms
I0514 20:45:43.900982 36798 replica.cpp:676] Persisted action at 1
I0514 20:45:43.901008 36798 replica.cpp:661] Replica learned APPEND action at position 1
I0514 20:45:43.902535 36812 registrar.cpp:479] Successfully updated 'registry'
I0514 20:45:43.902695 36812 registrar.cpp:372] Successfully recovered registrar
I0514 20:45:43.902731 36816 log.cpp:699] Attempting to truncate the log to 1
I0514 20:45:43.902936 36804 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0514 20:45:43.902962 36805 master.cpp:777] Recovered 0 slaves from the Registry (117B) ; allowing 10mins for slaves to re-register
I0514 20:45:43.904026 36799 replica.cpp:508] Replica received write request for position 2
I0514 20:45:43.905686 36778 mesos_containerizer.cpp:122] Using isolation: cgroups/cpu,cgroups/mem
I0514 20:45:43.909281 36799 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.203581ms
I0514 20:45:43.909320 36799 replica.cpp:676] Persisted action at 2
I0514 20:45:43.909922 36795 replica.cpp:655] Replica received learned notice for position 2
I0514 20:45:43.917597 36795 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.625126ms
I0514 20:45:43.917716 36795 leveldb.cpp:401] Deleting ~1 keys from leveldb took 25746ns
I0514 20:45:43.917744 36795 replica.cpp:676] Persisted action at 2
I0514 20:45:43.917799 36795 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0514 20:45:43.956254 36778 linux_launcher.cpp:66] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0514 20:45:43.960209 36793 slave.cpp:143] Slave started on 14)@10.35.255.108:57356
I0514 20:45:43.960284 36793 slave.cpp:152] Moving slave process into its own cgroup
I0514 20:45:43.963740 36778 sched.cpp:121] Version: 0.19.0
I0514 20:45:43.964298 36800 sched.cpp:217] New master detected at master@10.35.255.108:57356
I0514 20:45:43.964359 36800 sched.cpp:268] Authenticating with master master@10.35.255.108:57356
I0514 20:45:43.964944 36811 authenticatee.hpp:128] Creating new client SASL connection
I0514 20:45:43.965106 36811 master.cpp:2803] Authenticating scheduler(8)@10.35.255.108:57356
I0514 20:45:43.965680 36794 authenticator.hpp:148] Creating new server SASL connection
I0514 20:45:43.966018 36794 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0514 20:45:43.966141 36794 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0514 20:45:43.966218 36794 authenticator.hpp:254] Received SASL authentication start
I0514 20:45:43.966291 36794 authenticator.hpp:342] Authentication requires more steps
I0514 20:45:43.966361 36794 authenticatee.hpp:265] Received SASL authentication step
I0514 20:45:43.966521 36794 authenticator.hpp:282] Received SASL authentication step
I0514 20:45:43.966642 36794 authenticator.hpp:334] Authentication success
I0514 20:45:43.966730 36810 master.cpp:2843] Successfully authenticated scheduler(8)@10.35.255.108:57356
I0514 20:45:43.966733 36805 authenticatee.hpp:305] Authentication success
I0514 20:45:43.967176 36805 sched.cpp:342] Successfully authenticated with master master@10.35.255.108:57356
I0514 20:45:43.967331 36814 master.cpp:978] Received registration request from scheduler(8)@10.35.255.108:57356
I0514 20:45:43.967427 36814 master.cpp:996] Registering framework 20140514-204543-1828659978-57356-36778-0000 at scheduler(8)@10.35.255.108:57356
I0514 20:45:43.967639 36806 sched.cpp:392] Framework registered with 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:43.967727 36801 hierarchical_allocator_process.hpp:331] Added framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:43.972489 36793 slave.cpp:152] Moving slave process into its own cgroup
I0514 20:45:43.978257 36793 credentials.hpp:35] Loading credentials for authentication
W0514 20:45:43.978394 36793 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_RemoveNonCheckpointingFramework_CN6t3w/credential': No such file or directory
I0514 20:45:43.978446 36793 slave.cpp:239] Slave using credential for: test-principal
I0514 20:45:43.978675 36793 slave.cpp:252] Slave resources: cpus
:2; mem:1024; disk:1024; ports:[31000-32000]
I0514 20:45:43.979122 36793 slave.cpp:280] Slave hostname: smfd-atr-11-sr1.devel.twitter.com
I0514 20:45:43.979161 36793 slave.cpp:281] Slave checkpoint: true
I0514 20:45:43.980404 36798 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_RemoveNonCheckpointingFramework_CN6t3w/meta'
I0514 20:45:43.980890 36803 status_update_manager.cpp:193] Recovering status update manager
I0514 20:45:43.981730 36806 mesos_containerizer.cpp:279] Recovering containerizer
I0514 20:45:43.983495 36795 mem.cpp:165] Removing orphaned cgroup 'mesos_test_d6f332f1-3598-460e-a74e-5749a7bf7ac6/slave'
I0514 20:45:43.984102 36814 cpushare.cpp:189] Removing orphaned cgroup 'cpuacct/mesos_test_d6f332f1-3598-460e-a74e-5749a7bf7ac6/slave'
I0514 20:45:43.987674 36801 slave.cpp:2975] Finished recovery
I0514 20:45:43.988082 36807 slave.cpp:533] New master detected at master@10.35.255.108:57356
I0514 20:45:43.988185 36807 slave.cpp:575] Detecting new master
I0514 20:45:43.988185 36803 status_update_manager.cpp:167] New master detected at master@10.35.255.108:57356
I0514 20:45:43.993654 36803 slave.cpp:602] Authenticating with master master@10.35.255.108:57356
I0514 20:45:43.993875 36795 authenticatee.hpp:128] Creating new client SASL connection
I0514 20:45:43.994104 36799 master.cpp:2803] Authenticating slave(14)@10.35.255.108:57356
I0514 20:45:43.994382 36800 authenticator.hpp:148] Creating new server SASL connection
I0514 20:45:43.994673 36809 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0514 20:45:43.994724 36809 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0514 20:45:43.994840 36796 authenticator.hpp:254] Received SASL authentication start
I0514 20:45:43.994940 36796 authenticator.hpp:342] Authentication requires more steps
I0514 20:45:43.995050 36796 authenticatee.hpp:265] Received SASL authentication step
I0514 20:45:43.995323 36813 authenticator.hpp:282] Received SASL authentication step
I0514 20:45:43.995424 36813 authenticator.hpp:334] Authentication success
I0514 20:45:43.995553 36805 master.cpp:2843] Successfully authenticated slave(14)@10.35.255.108:57356
I0514 20:45:43.995612 36793 authenticatee.hpp:305] Authentication success
I0514 20:45:43.996165 36797 slave.cpp:659] Successfully authenticated with master master@10.35.255.108:57356
I0514 20:45:43.996450 36811 master.cpp:2134] Registering slave at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) with id 20140514-204543-1828659978-57356-36778-0
I0514 20:45:43.996803 36802 registrar.cpp:422] Attempting to update the 'registry'
I0514 20:45:43.999317 36793 log.cpp:680] Attempting to append 382 bytes to the log
I0514 20:45:43.999510 36802 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0514 20:45:44.000373 36801 replica.cpp:508] Replica received write request for position 3
I0514 20:45:44.013892 36812 master.cpp:2122] Ignoring register slave message from slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0514 20:45:44.017613 36801 leveldb.cpp:343] Persisting action (401 bytes) to leveldb took 17.134038ms
I0514 20:45:44.017695 36801 replica.cpp:676] Persisted action at 3
I0514 20:45:44.018345 36797 replica.cpp:655] Replica received learned notice for position 3
I0514 20:45:44.028404 36809 master.cpp:2122] Ignoring register slave message from slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0514 20:45:44.067612 36797 leveldb.cpp:343] Persisting action (403 bytes) to leveldb took 49.185909ms
I0514 20:45:44.067726 36797 replica.cpp:676] Persisted action at 3
I0514 20:45:44.067757 36797 replica.cpp:661] Replica learned APPEND action at position 3
I0514 20:45:44.068979 36803 master.cpp:2122] Ignoring register slave message from slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0514 20:45:44.069107 36811 registrar.cpp:479] Successfully updated 'registry'
I0514 20:45:44.069480 36806 log.cpp:699] Attempting to truncate the log to 3
I0514 20:45:44.069710 36803 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0514 20:45:44.069906 36815 master.cpp:2174] Registered slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:44.069944 36815 master.cpp:3288] Adding slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0514 20:45:44.070243 36802 slave.cpp:693] Registered with master master@10.35.255.108:57356; given slave ID 20140514-204543-1828659978-57356-36778-0
I0514 20:45:44.070466 36802 slave.cpp:706] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RemoveNonCheckpointingFramework_CN6t3w/meta/slaves/20140514-204543-1828659978-57356-36778-0/slave.info'
I0514 20:45:44.070592 36807 replica.cpp:508] Replica received write request for position 4
I0514 20:45:44.070713 36793 hierarchical_allocator_process.hpp:444] Added slave 20140514-204543-1828659978-57356-36778-0 (smfd-atr-11-sr1.devel.twitter.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (and cpus:2; mem:1024; disk:1024; ports:[31000-32000] available)
I0514 20:45:44.071257 36793 master.cpp:2752] Sending 1 offers to framework 20140514-204543-1828659978-57356-36778-0000
W0514 20:45:44.076079 36794 sched.cpp:902] Attempting to launch task 211518ed-53dd-446e-991d-d40d1b78df72 with an unknown offer 20140514-204543-1828659978-57356-36778-0
I0514 20:45:44.076701 36793 master.cpp:1810] Processing reply for offers: [ 20140514-204543-1828659978-57356-36778-0 ] on slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com) for framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.076871 36793 master.hpp:608] Adding task 8f43e6d0-6f87-491a-84b6-83c103d118ec with resources cpus:1; mem:512 on slave 20140514-204543-1828659978-57356-36778-0 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:44.076935 36793 master.cpp:2927] Launching task 8f43e6d0-6f87-491a-84b6-83c103d118ec of framework 20140514-204543-1828659978-57356-36778-0000 with resources cpus:1; mem:512 on slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:44.077231 36793 master.hpp:608] Adding task 211518ed-53dd-446e-991d-d40d1b78df72 with resources cpus:1; mem:512 on slave 20140514-204543-1828659978-57356-36778-0 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:44.077265 36794 slave.cpp:920] Got assigned task 8f43e6d0-6f87-491a-84b6-83c103d118ec for framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.077301 36793 master.cpp:2927] Launching task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000 with resources cpus:1; mem:512 on slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:44.077832 36800 hierarchical_allocator_process.hpp:589] Framework 20140514-204543-1828659978-57356-36778-0000 filtered slave 20140514-204543-1828659978-57356-36778-0 for 5secs
I0514 20:45:44.077859 36794 slave.cpp:920] Got assigned task 211518ed-53dd-446e-991d-d40d1b78df72 for framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.078202 36794 slave.cpp:1030] Launching task 8f43e6d0-6f87-491a-84b6-83c103d118ec for framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.080832 36813 mesos_containerizer.cpp:523] Starting container '62489f61-2c47-44be-8cee-7f2dd6079908' for executor '8f43e6d0-6f87-491a-84b6-83c103d118ec' of framework '20140514-204543-1828659978-57356-36778-0000'
I0514 20:45:44.080852 36794 slave.cpp:1140] Queuing task '8f43e6d0-6f87-491a-84b6-83c103d118ec' for executor 8f43e6d0-6f87-491a-84b6-83c103d118ec of framework '20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.080966 36794 slave.cpp:1030] Launching task 211518ed-53dd-446e-991d-d40d1b78df72 for framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.083236 36815 mem.cpp:413] Started listening for OOM events for container 62489f61-2c47-44be-8cee-7f2dd6079908
I0514 20:45:44.083644 36798 mesos_containerizer.cpp:523] Starting container '10130c74-7ab3-462e-9206-576c568294c9' for executor '211518ed-53dd-446e-991d-d40d1b78df72' of framework '20140514-204543-1828659978-57356-36778-0000'
I0514 20:45:44.083695 36794 slave.cpp:1140] Queuing task '211518ed-53dd-446e-991d-d40d1b78df72' for executor 211518ed-53dd-446e-991d-d40d1b78df72 of framework '20140514-204543-1828659978-57356-36778-0000
I0514 20:45:44.083884 36815 mem.cpp:277] Updated 'memory.soft_limit_in_bytes' to 512MB for container 62489f61-2c47-44be-8cee-7f2dd6079908
I0514 20:45:44.084671 36804 cpushare.cpp:334] Updated 'cpu.shares' to 1024 (cpus 1) for container 62489f61-2c47-44be-8cee-7f2dd6079908
I0514 20:45:44.085093 36815 mem.cpp:307] Updated 'memory.limit_in_bytes' to 512MB for container 62489f61-2c47-44be-8cee-7f2dd6079908
I0514 20:45:44.087297 36813 linux_launcher.cpp:222] Cloning child process with flags = 0
I0514 20:45:44.088526 36815 mem.cpp:413] Started listening for OOM events for container 10130c74-7ab3-462e-9206-576c568294c9
I0514 20:45:44.092516 36807 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 21.862391ms
I0514 20:45:44.092689 36807 replica.cpp:676] Persisted action at 4
I0514 20:45:44.093760 36816 replica.cpp:655] Replica received learned notice for position 4
I0514 20:45:44.100843 36816 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.03076ms
I0514 20:45:44.100983 36816 leveldb.cpp:401] Deleting ~2 keys from leveldb took 34100ns
I0514 20:45:44.101011 36816 replica.cpp:676] Persisted action at 4
I0514 20:45:44.101039 36816 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0514 20:45:44.135138 36815 mem.cpp:277] Updated 'memory.soft_limit_in_bytes' to 512MB for container 10130c74-7ab3-462e-9206-576c568294c9
I0514 20:45:44.136108 36804 cpushare.cpp:334] Updated 'cpu.shares' to 1024 (cpus 1) for container 10130c74-7ab3-462e-9206-576c568294c9
I0514 20:45:44.136598 36815 mem.cpp:307] Updated 'memory.limit_in_bytes' to 512MB for container 10130c74-7ab3-462e-9206-576c568294c9
I0514 20:45:44.239186 36797 linux_launcher.cpp:222] Cloning child process with flags = 0
I0514 20:45:44.243119 36797 mesos_containerizer.cpp:623] Fetching URIs for container '62489f61-2c47-44be-8cee-7f2dd6079908' using command '/home/vinod/mesos/build/src/mesos-fetcher'
I0514 20:45:44.259407 36802 mesos_containerizer.cpp:623] Fetching URIs for container '10130c74-7ab3-462e-9206-576c568294c9' using command '/home/vinod/mesos/build/src/mesos-fetcher'
I0514 20:45:45.252585 36810 slave.cpp:2312] Monitoring executor '8f43e6d0-6f87-491a-84b6-83c103d118ec' of framework '20140514-204543-1828659978-57356-36778-0000' in container '62489f61-2c47-44be-8cee-7f2dd6079908'
I0514 20:45:45.253128 36810 slave.cpp:2312] Monitoring executor '211518ed-53dd-446e-991d-d40d1b78df72' of framework '20140514-204543-1828659978-57356-36778-0000' in container '10130c74-7ab3-462e-9206-576c568294c9'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0514 20:45:45.303606 37377 exec.cpp:131] Version: 0.19.0
I0514 20:45:45.310616 36810 slave.cpp:1620] Got registration for executor '211518ed-53dd-446e-991d-d40d1b78df72' of framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:45.311265 36810 slave.cpp:1739] Flushing queued task 211518ed-53dd-446e-991d-d40d1b78df72 for executor '211518ed-53dd-446e-991d-d40d1b78df72' of framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:45.312124 37438 exec.cpp:205] Executor registered on slave 20140514-204543-1828659978-57356-36778-0
I0514 20:45:45.312604 36800 mem.cpp:277] Updated 'memory.soft_limit_in_bytes' to 512MB for container 10130c74-7ab3-462e-9206-576c568294c9
I0514 20:45:45.312749 36813 cpushare.cpp:334] Updated 'cpu.shares' to 1024 (cpus 1) for container 10130c74-7ab3-462e-9206-576c568294c9
Registered executor on smfd-atr-11-sr1.devel.twitter.com
Starting task 211518ed-53dd-446e-991d-d40d1b78df72
sh -c 'sleep 1000'
Forked command at 37457
I0514 20:45:45.319758 36800 slave.cpp:1975] Handling status update TASK_RUNNING (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000 from executor(1)@10.35.255.108:39534
I0514 20:45:45.320253 36800 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000
I0514 20:45:45.320729 36800 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000 to master@10.35.255.108:57356
I0514 20:45:45.321002 36794 slave.cpp:2102] Sending acknowledgement for status update TASK_RUNNING (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000 to executor(1)@10.35.255.108:39534
I0514 20:45:45.321107 36811 master.cpp:2452] Status update TASK_RUNNING (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000 from slave 20140514-204543-1828659978-57356-36778-0 at slave(14)@10.35.255.108:57356 (smfd-atr-11-sr1.devel.twitter.com)
I0514 20:45:45.322562 36812 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b1910817-32f3-4ab6-8169-11a3c0ea3d7b) for task 211518ed-53dd-446e-991d-d40d1b78df72 of framework 20140514-204543-1828659978-57356-36778-0000
../../src/tests/slave_recovery_tests.cpp:1076: Failure
Failed to wait 10secs for update2