[jira] [Reopened] (MESOS-1348) The SlaveRecoveryTest.GCExecutor test leaks child processes.

["Benjamin Mahler (JIRA)" <ji...@apache.org>]

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

Benjamin Mahler reopened MESOS-1348:
------------------------------------

      Assignee: Benjamin Mahler

This did not get fixed:

{noformat}
[ RUN      ] SlaveRecoveryTest/0.GCExecutor
Using temporary directory '/tmp/SlaveRecoveryTest_0_GCExecutor_QuV5Sj'
I0611 18:09:22.407665  6066 leveldb.cpp:176] Opened db in 39.270068ms
I0611 18:09:22.419929  6066 leveldb.cpp:183] Compacted db in 12.235671ms
I0611 18:09:22.419963  6066 leveldb.cpp:198] Created db iterator in 4688ns
I0611 18:09:22.419975  6066 leveldb.cpp:204] Seeked to beginning of db in 637ns
I0611 18:09:22.419983  6066 leveldb.cpp:273] Iterated through 0 keys in the db in 281ns
I0611 18:09:22.419997  6066 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0611 18:09:22.420238  6110 recover.cpp:425] Starting replica recovery
I0611 18:09:22.420826  6096 recover.cpp:451] Replica is in EMPTY status
I0611 18:09:22.422265  6097 master.cpp:280] Master 20140611-180922-453759884-56092-6066 (hemera.apache.org) started on 140.211.11.27:56092
I0611 18:09:22.422294  6097 master.cpp:317] Master only allowing authenticated frameworks to register
I0611 18:09:22.422307  6097 master.cpp:322] Master only allowing authenticated slaves to register
I0611 18:09:22.422322  6097 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_GCExecutor_QuV5Sj/credentials'
I0611 18:09:22.422559  6097 master.cpp:348] Authorization enabled
I0611 18:09:22.422981  6103 master.cpp:114] No whitelist given. Advertising offers for all slaves
I0611 18:09:22.423272  6113 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@140.211.11.27:56092
I0611 18:09:22.424098  6103 master.cpp:961] The newly elected leader is master@140.211.11.27:56092 with id 20140611-180922-453759884-56092-6066
I0611 18:09:22.424208  6103 master.cpp:974] Elected as the leading master!
I0611 18:09:22.424176  6094 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0611 18:09:22.424217  6103 master.cpp:792] Recovering from registrar
I0611 18:09:22.424361  6110 registrar.cpp:313] Recovering registrar
I0611 18:09:22.424499  6105 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0611 18:09:22.425021  6101 recover.cpp:542] Updating replica status to STARTING
I0611 18:09:22.440032  6115 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.334449ms
I0611 18:09:22.440063  6115 replica.cpp:320] Persisted replica status to STARTING
I0611 18:09:22.440155  6115 recover.cpp:451] Replica is in STARTING status
I0611 18:09:22.441633  6105 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0611 18:09:22.442536  6101 recover.cpp:188] Received a recover response from a replica in STARTING status
I0611 18:09:22.443089  6096 recover.cpp:542] Updating replica status to VOTING
I0611 18:09:22.460113  6094 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.111575ms
I0611 18:09:22.460145  6094 replica.cpp:320] Persisted replica status to VOTING
I0611 18:09:22.460197  6094 recover.cpp:556] Successfully joined the Paxos group
I0611 18:09:22.460274  6094 recover.cpp:440] Recover process terminated
I0611 18:09:22.461905  6100 log.cpp:656] Attempting to start the writer
I0611 18:09:22.464913  6103 replica.cpp:474] Replica received implicit promise request with proposal 1
I0611 18:09:22.480170  6103 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 15.231311ms
I0611 18:09:22.480202  6103 replica.cpp:342] Persisted promised to 1
I0611 18:09:22.480550  6094 coordinator.cpp:230] Coordinator attemping to fill missing position
I0611 18:09:22.484205  6100 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0611 18:09:22.500361  6100 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 16.117082ms
I0611 18:09:22.500393  6100 replica.cpp:676] Persisted action at 0
I0611 18:09:22.502578  6116 replica.cpp:508] Replica received write request for position 0
I0611 18:09:22.502614  6116 leveldb.cpp:438] Reading position from leveldb took 15182ns
I0611 18:09:22.520419  6116 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 17.787509ms
I0611 18:09:22.520452  6116 replica.cpp:676] Persisted action at 0
I0611 18:09:22.520931  6095 replica.cpp:655] Replica received learned notice for position 0
I0611 18:09:22.536460  6095 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.503718ms
I0611 18:09:22.536494  6095 replica.cpp:676] Persisted action at 0
I0611 18:09:22.536505  6095 replica.cpp:661] Replica learned NOP action at position 0
I0611 18:09:22.537117  6095 log.cpp:672] Writer started with ending position 0
I0611 18:09:22.538629  6112 leveldb.cpp:438] Reading position from leveldb took 11718ns
I0611 18:09:22.541352  6104 registrar.cpp:346] Successfully fetched the registry (0B)
I0611 18:09:22.541380  6104 registrar.cpp:422] Attempting to update the 'registry'
I0611 18:09:22.543668  6108 log.cpp:680] Attempting to append 137 bytes to the log
I0611 18:09:22.544006  6095 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0611 18:09:22.546057  6102 replica.cpp:508] Replica received write request for position 1
I0611 18:09:22.560612  6102 leveldb.cpp:343] Persisting action (156 bytes) to leveldb took 14.5303ms
I0611 18:09:22.560645  6102 replica.cpp:676] Persisted action at 1
I0611 18:09:22.561609  6107 replica.cpp:655] Replica received learned notice for position 1
I0611 18:09:22.576684  6107 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 15.050446ms
I0611 18:09:22.576717  6107 replica.cpp:676] Persisted action at 1
I0611 18:09:22.576730  6107 replica.cpp:661] Replica learned APPEND action at position 1
I0611 18:09:22.577201  6106 registrar.cpp:479] Successfully updated 'registry'
I0611 18:09:22.577509  6106 registrar.cpp:372] Successfully recovered registrar
I0611 18:09:22.577826  6097 log.cpp:699] Attempting to truncate the log to 1
I0611 18:09:22.577891  6097 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0611 18:09:22.578626  6101 master.cpp:819] Recovered 0 slaves from the Registry (99B) ; allowing 10mins for slaves to re-register
I0611 18:09:22.580059  6066 mesos_containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
I0611 18:09:22.581339  6098 replica.cpp:508] Replica received write request for position 2
I0611 18:09:22.583959  6100 slave.cpp:143] Slave started on 179)@140.211.11.27:56092
I0611 18:09:22.583983  6100 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/credential'
I0611 18:09:22.584244  6100 slave.cpp:243] Slave using credential for: test-principal
I0611 18:09:22.584372  6100 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0611 18:09:22.584455  6100 slave.cpp:284] Slave hostname: hemera.apache.org
I0611 18:09:22.584475  6100 slave.cpp:285] Slave checkpoint: true
I0611 18:09:22.584832  6100 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta'
I0611 18:09:22.585091  6107 status_update_manager.cpp:193] Recovering status update manager
I0611 18:09:22.585330  6095 mesos_containerizer.cpp:281] Recovering containerizer
I0611 18:09:22.586227  6109 slave.cpp:3024] Finished recovery
I0611 18:09:22.587571  6066 sched.cpp:128] Version: 0.20.0
I0611 18:09:22.587999  6112 sched.cpp:224] New master detected at master@140.211.11.27:56092
I0611 18:09:22.588026  6112 sched.cpp:274] Authenticating with master master@140.211.11.27:56092
I0611 18:09:22.588649  6111 authenticatee.hpp:128] Creating new client SASL connection
I0611 18:09:22.588877  6111 master.cpp:3341] Authenticating scheduler(171)@140.211.11.27:56092
I0611 18:09:22.589025  6114 authenticator.hpp:156] Creating new server SASL connection
I0611 18:09:22.589262  6114 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0611 18:09:22.589284  6114 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0611 18:09:22.589604  6097 authenticator.hpp:262] Received SASL authentication start
I0611 18:09:22.589701  6097 authenticator.hpp:384] Authentication requires more steps
I0611 18:09:22.589748  6097 authenticatee.hpp:265] Received SASL authentication step
I0611 18:09:22.589794  6097 authenticator.hpp:290] Received SASL authentication step
I0611 18:09:22.589846  6097 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0611 18:09:22.589855  6097 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0611 18:09:22.589865  6097 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0611 18:09:22.589876  6097 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0611 18:09:22.589884  6097 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:22.589890  6097 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:22.589902  6097 authenticator.hpp:376] Authentication success
I0611 18:09:22.589937  6097 authenticatee.hpp:305] Authentication success
I0611 18:09:22.590030  6106 master.cpp:3381] Successfully authenticated principal 'test-principal' at scheduler(171)@140.211.11.27:56092
I0611 18:09:22.590306  6097 sched.cpp:348] Successfully authenticated with master master@140.211.11.27:56092
I0611 18:09:22.590330  6097 sched.cpp:467] Sending registration request to master@140.211.11.27:56092
I0611 18:09:22.590531  6105 master.cpp:1080] Received registration request from scheduler(171)@140.211.11.27:56092
I0611 18:09:22.590564  6105 master.cpp:1040] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0611 18:09:22.591091  6108 master.cpp:1139] Registering framework 20140611-180922-453759884-56092-6066-0000 at scheduler(171)@140.211.11.27:56092
I0611 18:09:22.591194  6108 sched.cpp:398] Framework registered with 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.591223  6108 sched.cpp:412] Scheduler::registered took 14824ns
I0611 18:09:22.591269  6095 hierarchical_allocator_process.hpp:331] Added framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.591295  6095 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0611 18:09:22.591306  6095 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 13366ns
I0611 18:09:22.593075  6109 slave.cpp:537] New master detected at master@140.211.11.27:56092
I0611 18:09:22.593281  6109 slave.cpp:613] Authenticating with master master@140.211.11.27:56092
I0611 18:09:22.593309  6111 status_update_manager.cpp:167] New master detected at master@140.211.11.27:56092
I0611 18:09:22.593399  6109 slave.cpp:586] Detecting new master
I0611 18:09:22.593963  6111 authenticatee.hpp:128] Creating new client SASL connection
I0611 18:09:22.594105  6111 master.cpp:3341] Authenticating slave(179)@140.211.11.27:56092
I0611 18:09:22.594220  6109 authenticator.hpp:156] Creating new server SASL connection
I0611 18:09:22.594338  6109 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0611 18:09:22.594358  6109 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0611 18:09:22.594511  6099 authenticator.hpp:262] Received SASL authentication start
I0611 18:09:22.594609  6099 authenticator.hpp:384] Authentication requires more steps
I0611 18:09:22.594890  6110 authenticatee.hpp:265] Received SASL authentication step
I0611 18:09:22.595300  6116 authenticator.hpp:290] Received SASL authentication step
I0611 18:09:22.595329  6116 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0611 18:09:22.595340  6116 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0611 18:09:22.595350  6116 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0611 18:09:22.595360  6116 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0611 18:09:22.595367  6116 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:22.595373  6116 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:22.595386  6116 authenticator.hpp:376] Authentication success
I0611 18:09:22.595429  6116 authenticatee.hpp:305] Authentication success
I0611 18:09:22.595504  6108 master.cpp:3381] Successfully authenticated principal 'test-principal' at slave(179)@140.211.11.27:56092
I0611 18:09:22.595824  6101 slave.cpp:670] Successfully authenticated with master master@140.211.11.27:56092
I0611 18:09:22.595876  6101 slave.cpp:908] Will retry registration in 14.589338ms if necessary
I0611 18:09:22.595935  6108 master.cpp:2620] Registering slave at slave(179)@140.211.11.27:56092 (hemera.apache.org) with id 20140611-180922-453759884-56092-6066-0
I0611 18:09:22.596063  6108 registrar.cpp:422] Attempting to update the 'registry'
I0611 18:09:22.596840  6098 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.477771ms
I0611 18:09:22.596865  6098 replica.cpp:676] Persisted action at 2
I0611 18:09:22.597432  6096 replica.cpp:655] Replica received learned notice for position 2
I0611 18:09:22.609197  6096 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.744868ms
I0611 18:09:22.609266  6096 leveldb.cpp:401] Deleting ~1 keys from leveldb took 39134ns
I0611 18:09:22.609280  6096 replica.cpp:676] Persisted action at 2
I0611 18:09:22.609290  6096 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0611 18:09:22.609598  6096 log.cpp:680] Attempting to append 330 bytes to the log
I0611 18:09:22.609856  6103 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0611 18:09:22.611399  6095 slave.cpp:908] Will retry registration in 28.673101ms if necessary
I0611 18:09:22.611459  6116 master.cpp:2608] Ignoring register slave message from slave(179)@140.211.11.27:56092 (hemera.apache.org) as admission is already in progress
I0611 18:09:22.611529  6099 replica.cpp:508] Replica received write request for position 3
I0611 18:09:22.625231  6099 leveldb.cpp:343] Persisting action (349 bytes) to leveldb took 13.6027ms
I0611 18:09:22.625260  6099 replica.cpp:676] Persisted action at 3
I0611 18:09:22.625663  6095 replica.cpp:655] Replica received learned notice for position 3
I0611 18:09:22.637398  6095 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 11.70563ms
I0611 18:09:22.637430  6095 replica.cpp:676] Persisted action at 3
I0611 18:09:22.637442  6095 replica.cpp:661] Replica learned APPEND action at position 3
I0611 18:09:22.637837  6113 registrar.cpp:479] Successfully updated 'registry'
I0611 18:09:22.638219  6110 log.cpp:699] Attempting to truncate the log to 3
I0611 18:09:22.638537  6103 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0611 18:09:22.638723  6098 master.cpp:2660] Registered slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org)
I0611 18:09:22.638751  6098 master.cpp:3763] Adding slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0611 18:09:22.639608  6103 slave.cpp:704] Registered with master master@140.211.11.27:56092; given slave ID 20140611-180922-453759884-56092-6066-0
I0611 18:09:22.639793  6107 hierarchical_allocator_process.hpp:444] Added slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0611 18:09:22.639883  6107 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 to framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.639904  6103 slave.cpp:717] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/slave.info'
I0611 18:09:22.640202  6107 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140611-180922-453759884-56092-6066-0 in 353848ns
I0611 18:09:22.640506  6114 replica.cpp:508] Replica received write request for position 4
I0611 18:09:22.640496  6116 master.hpp:720] Adding offer 20140611-180922-453759884-56092-6066-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:22.640701  6116 master.cpp:3288] Sending 1 offers to framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.640862  6116 sched.cpp:535] Scheduler::resourceOffers took 52068ns
I0611 18:09:22.643621  6103 master.hpp:730] Removing offer 20140611-180922-453759884-56092-6066-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:22.643688  6103 master.cpp:1964] Processing reply for offers: [ 20140611-180922-453759884-56092-6066-0 ] on slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org) for framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.643725  6103 master.cpp:2050] Authorizing framework principal 'test-principal' to launch task 484defad-2ea5-49af-bbb5-2603ac98755f as user 'jenkins'
I0611 18:09:22.644215  6094 master.hpp:692] Adding task 484defad-2ea5-49af-bbb5-2603ac98755f with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:22.644282  6094 master.cpp:2116] Launching task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org)
I0611 18:09:22.644593  6113 slave.cpp:939] Got assigned task 484defad-2ea5-49af-bbb5-2603ac98755f for framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.644711  6113 slave.cpp:3296] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/framework.info'
I0611 18:09:22.644882  6113 slave.cpp:3303] Checkpointing framework pid 'scheduler(171)@140.211.11.27:56092' to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/framework.pid'
I0611 18:09:22.645186  6113 slave.cpp:1049] Launching task 484defad-2ea5-49af-bbb5-2603ac98755f for framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.650022  6113 slave.cpp:3618] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f/executor.info'
I0611 18:09:22.653748  6114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.156887ms
I0611 18:09:22.653777  6114 replica.cpp:676] Persisted action at 4
I0611 18:09:22.654528  6101 replica.cpp:655] Replica received learned notice for position 4
I0611 18:09:22.661808  6113 slave.cpp:3733] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f/runs/1c1fddd7-b463-460b-a454-04cfac3c7b05/tasks/484defad-2ea5-49af-bbb5-2603ac98755f/task.info'
I0611 18:09:22.661820  6094 mesos_containerizer.cpp:537] Starting container '1c1fddd7-b463-460b-a454-04cfac3c7b05' for executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework '20140611-180922-453759884-56092-6066-0000'
I0611 18:09:22.662014  6113 slave.cpp:1159] Queuing task '484defad-2ea5-49af-bbb5-2603ac98755f' for executor 484defad-2ea5-49af-bbb5-2603ac98755f of framework '20140611-180922-453759884-56092-6066-0000
I0611 18:09:22.662088  6113 slave.cpp:498] Successfully attached file '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f/runs/1c1fddd7-b463-460b-a454-04cfac3c7b05'
I0611 18:09:22.665962  6093 launcher.cpp:117] Forked child with pid '9665' for container '1c1fddd7-b463-460b-a454-04cfac3c7b05'
I0611 18:09:22.666050  6093 mesos_containerizer.cpp:803] Checkpointing executor's forked pid 9665 to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f/runs/1c1fddd7-b463-460b-a454-04cfac3c7b05/pids/forked.pid'
I0611 18:09:22.673604  6112 mesos_containerizer.cpp:647] Fetching URIs for container '1c1fddd7-b463-460b-a454-04cfac3c7b05' using command '/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src/mesos-fetcher'
I0611 18:09:22.675812  6101 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 21.169124ms
I0611 18:09:22.676280  6101 leveldb.cpp:401] Deleting ~2 keys from leveldb took 316496ns
I0611 18:09:22.676374  6101 replica.cpp:676] Persisted action at 4
I0611 18:09:22.676468  6101 replica.cpp:661] Replica learned TRUNCATE action at position 4
2014-06-11 18:09:22,705:6066(0x2b23ad136700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:39888] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0611 18:09:23.322206  6098 slave.cpp:2361] Monitoring executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework '20140611-180922-453759884-56092-6066-0000' in container '1c1fddd7-b463-460b-a454-04cfac3c7b05'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0611 18:09:23.361429  9687 process.cpp:1671] libprocess is initialized on 140.211.11.27:49926 for 24 cpus
I0611 18:09:23.363090  9687 exec.cpp:131] Version: 0.20.0
I0611 18:09:23.365003  9716 exec.cpp:181] Executor started at: executor(1)@140.211.11.27:49926 with pid 9687
I0611 18:09:23.366451  6098 slave.cpp:1670] Got registration for executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.366729  6098 slave.cpp:1755] Checkpointing executor pid 'executor(1)@140.211.11.27:49926' to '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f/runs/1c1fddd7-b463-460b-a454-04cfac3c7b05/pids/libprocess.pid'
I0611 18:09:23.367902  6098 slave.cpp:1789] Flushing queued task 484defad-2ea5-49af-bbb5-2603ac98755f for executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.368001  6117 process.cpp:1098] Socket closed while receiving
I0611 18:09:23.368222  6117 process.cpp:1098] Socket closed while receiving
I0611 18:09:23.368273  9725 process.cpp:1037] Socket closed while receiving
I0611 18:09:23.368427  9707 exec.cpp:205] Executor registered on slave 20140611-180922-453759884-56092-6066-0
I0611 18:09:23.368556  9725 process.cpp:1037] Socket closed while receiving
I0611 18:09:23.370321  9707 exec.cpp:217] Executor::registered took 105109ns
Registered executor on hemera.apache.org
I0611 18:09:23.370617  9707 exec.cpp:292] Executor asked to run task '484defad-2ea5-49af-bbb5-2603ac98755f'
I0611 18:09:23.370755  9707 exec.cpp:301] Executor::launchTask took 119632ns
Starting task 484defad-2ea5-49af-bbb5-2603ac98755f
Forked command at 9726
sh -c 'sleep 1000'
I0611 18:09:23.373865  9707 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.374501  6096 slave.cpp:2024] Handling status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 from executor(1)@140.211.11.27:49926
I0611 18:09:23.375329  6101 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.375382  6101 status_update_manager.cpp:499] Creating StatusUpdate stream for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.375630  6101 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.407505  6101 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 to master@140.211.11.27:56092
I0611 18:09:23.407867  6101 slave.cpp:2145] Status update manager successfully handled status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.407892  6101 slave.cpp:2151] Sending acknowledgement for status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 to executor(1)@140.211.11.27:49926
I0611 18:09:23.408125  6117 process.cpp:1098] Socket closed while receiving
I0611 18:09:23.408309  9725 process.cpp:1037] Socket closed while receiving
I0611 18:09:23.408709  9712 exec.cpp:338] Executor received status update acknowledgement c651c63b-46ee-4835-a902-80e108e6f867 for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.408896  6109 master.cpp:2946] Status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 from slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org)
I0611 18:09:23.409782  6110 sched.cpp:626] Scheduler::statusUpdate took 79047ns
I0611 18:09:23.411337  6066 slave.cpp:426] Slave terminating
I0611 18:09:23.411609  6110 master.cpp:716] Slave 20140611-180922-453759884-56092-6066-0 at slave(179)@140.211.11.27:56092 (hemera.apache.org) disconnected
I0611 18:09:23.411634  6110 master.cpp:1441] Disconnecting slave 20140611-180922-453759884-56092-6066-0
I0611 18:09:23.411860  6115 status_update_manager.cpp:398] Received status update acknowledgement (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.412149  6098 hierarchical_allocator_process.hpp:483] Slave 20140611-180922-453759884-56092-6066-0 disconnected
I0611 18:09:23.412526  6115 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: c651c63b-46ee-4835-a902-80e108e6f867) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.424588  6096 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 87192ns
I0611 18:09:23.447584  6117 process.cpp:1098] Socket closed while receiving
I0611 18:09:23.447671  9725 process.cpp:1037] Socket closed while receiving
I0611 18:09:23.447756  6066 mesos_containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
I0611 18:09:23.447881  9714 exec.cpp:378] Executor asked to shutdown
Shutting down
I0611 18:09:23.448698  9714 exec.cpp:393] Executor::shutdown took 335954ns
Sending SIGTERM to process tree at pid 9726
I0611 18:09:23.448963  9713 exec.cpp:77] Scheduling shutdown of the executor
I0611 18:09:23.452416  6097 slave.cpp:143] Slave started on 180)@140.211.11.27:56092
I0611 18:09:23.452436  6097 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/credential'
I0611 18:09:23.452507  6097 slave.cpp:243] Slave using credential for: test-principal
I0611 18:09:23.452606  6097 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0611 18:09:23.452678  6097 slave.cpp:284] Slave hostname: hemera.apache.org
I0611 18:09:23.452689  6097 slave.cpp:285] Slave checkpoint: true
I0611 18:09:23.454077  6112 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta'
W0611 18:09:23.454885  6112 state.cpp:331] Failed to find the latest run of executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.455539  6102 slave.cpp:3092] Recovering framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.455621  6102 slave.cpp:3468] Recovering executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000
W0611 18:09:23.455631  6102 slave.cpp:3474] Skipping recovery of executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000 because its latest run or executor info cannot be recovered
I0611 18:09:23.455827  6102 slave.cpp:2633] Cleaning up framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.456466  6100 status_update_manager.cpp:282] Closing status update streams for framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.456648  6104 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f' for gc 6.99998315208296days in the future
I0611 18:09:23.456915  6104 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f' for gc 6.99998315132148days in the future
I0611 18:09:23.457007  6104 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000' for gc 6.99999472078519days in the future
I0611 18:09:23.457044  6104 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000' for gc 6.99999472046222days in the future
I0611 18:09:23.457072  6103 status_update_manager.cpp:193] Recovering status update manager
I0611 18:09:23.457087  6103 status_update_manager.cpp:201] Recovering executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000
W0611 18:09:23.457095  6103 status_update_manager.cpp:205] Skipping recovering updates of executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000 because its info cannot be recovered
I0611 18:09:23.457460  6112 mesos_containerizer.cpp:281] Recovering containerizer
W0611 18:09:23.457479  6112 mesos_containerizer.cpp:289] Skipping recovery of executor '484defad-2ea5-49af-bbb5-2603ac98755f' of framework 20140611-180922-453759884-56092-6066-0000 because its info could not be recovered
I0611 18:09:23.459127  6107 slave.cpp:3024] Finished recovery
I0611 18:09:23.459596  6114 slave.cpp:537] New master detected at master@140.211.11.27:56092
I0611 18:09:23.459684  6114 slave.cpp:613] Authenticating with master master@140.211.11.27:56092
I0611 18:09:23.459719  6107 status_update_manager.cpp:167] New master detected at master@140.211.11.27:56092
I0611 18:09:23.459873  6114 slave.cpp:586] Detecting new master
I0611 18:09:23.460330  6098 authenticatee.hpp:128] Creating new client SASL connection
I0611 18:09:23.460494  6098 master.cpp:3341] Authenticating slave(180)@140.211.11.27:56092
I0611 18:09:23.460690  6107 authenticator.hpp:156] Creating new server SASL connection
I0611 18:09:23.461135  6107 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0611 18:09:23.461158  6107 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0611 18:09:23.461240  6098 authenticator.hpp:262] Received SASL authentication start
I0611 18:09:23.461357  6098 authenticator.hpp:384] Authentication requires more steps
I0611 18:09:23.461482  6098 authenticatee.hpp:265] Received SASL authentication step
I0611 18:09:23.462064  6095 authenticator.hpp:290] Received SASL authentication step
I0611 18:09:23.462095  6095 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0611 18:09:23.462105  6095 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0611 18:09:23.462118  6095 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0611 18:09:23.462129  6095 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0611 18:09:23.462136  6095 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:23.462142  6095 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0611 18:09:23.462157  6095 authenticator.hpp:376] Authentication success
I0611 18:09:23.462282  6106 authenticatee.hpp:305] Authentication success
I0611 18:09:23.462291  6095 master.cpp:3381] Successfully authenticated principal 'test-principal' at slave(180)@140.211.11.27:56092
I0611 18:09:23.463102  6097 slave.cpp:670] Successfully authenticated with master master@140.211.11.27:56092
I0611 18:09:23.463134  6097 slave.cpp:864] Reregistering completed framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.463346  6097 slave.cpp:908] Will retry registration in 707581ns if necessary
W0611 18:09:23.463582  6094 master.cpp:2735] Slave at slave(180)@140.211.11.27:56092 (hemera.apache.org) is being allowed to re-register with an already in use id (20140611-180922-453759884-56092-6066-0)
W0611 18:09:23.463635  6094 master.cpp:3443] Sending TASK_LOST for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 unknown to the slave 20140611-180922-453759884-56092-6066-0 at slave(180)@140.211.11.27:56092 (hemera.apache.org)
I0611 18:09:23.463744  6113 slave.cpp:754] Re-registered with master master@140.211.11.27:56092
I0611 18:09:23.465632  6094 master.cpp:2946] Status update TASK_LOST (UUID: 35cf8ea5-767e-4319-9091-2866873068ce) for task 484defad-2ea5-49af-bbb5-2603ac98755f of framework 20140611-180922-453759884-56092-6066-0000 from slave 20140611-180922-453759884-56092-6066-0 at slave(180)@140.211.11.27:56092 (hemera.apache.org)
I0611 18:09:23.465744  6094 master.hpp:710] Removing task 484defad-2ea5-49af-bbb5-2603ac98755f with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:23.465788  6116 sched.cpp:626] Scheduler::statusUpdate took 29512ns
I0611 18:09:23.466368  6100 hierarchical_allocator_process.hpp:635] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140611-180922-453759884-56092-6066-0 from framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.466426  6100 hierarchical_allocator_process.hpp:497] Slave 20140611-180922-453759884-56092-6066-0 reconnected
I0611 18:09:23.469547  6102 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 to framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.469701  6102 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 252508ns
I0611 18:09:23.469758  6097 master.hpp:720] Adding offer 20140611-180922-453759884-56092-6066-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:23.470064  6097 master.cpp:3288] Sending 1 offers to framework 20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.470458  6107 sched.cpp:535] Scheduler::resourceOffers took 21682ns
I0611 18:09:23.489907  6094 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 21863ns
I0611 18:09:23.489977  6112 master.cpp:114] No whitelist given. Advertising offers for all slaves
I0611 18:09:23.490080  6097 slave.cpp:2879] Current usage 72.01%. Max allowed age: 1.259059141164410days
I0611 18:09:23.490442  6111 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f
I0611 18:09:23.490674  6111 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f'
I0611 18:09:23.490732  6111 gc.cpp:167] Pruning directories with remaining removal time 0ns
I0611 18:09:23.490751  6111 gc.cpp:167] Pruning directories with remaining removal time 0ns
I0611 18:09:23.490761  6111 gc.cpp:167] Pruning directories with remaining removal time 0ns
I0611 18:09:23.490782  6111 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f
I0611 18:09:23.491219  6111 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000/executors/484defad-2ea5-49af-bbb5-2603ac98755f'
I0611 18:09:23.491287  6111 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.491389  6111 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000'
I0611 18:09:23.491431  6111 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000
I0611 18:09:23.491572  6111 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_SEhKci/meta/slaves/20140611-180922-453759884-56092-6066-0/frameworks/20140611-180922-453759884-56092-6066-0000'
I0611 18:09:23.491607  6111 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
I0611 18:09:23.491626  6111 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
Killing the following process trees:
[ 
-+- 9726 sh -c sleep 1000 
 \--- 9727 sleep 1000 
]
I0611 18:09:23.509793  6112 sched.cpp:731] Stopping framework '20140611-180922-453759884-56092-6066-0000'
I0611 18:09:23.509807  6066 master.cpp:575] Master terminating
I0611 18:09:23.509860  6066 master.hpp:730] Removing offer 20140611-180922-453759884-56092-6066-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140611-180922-453759884-56092-6066-0 (hemera.apache.org)
I0611 18:09:23.510624  6097 slave.cpp:2230] master@140.211.11.27:56092 exited
W0611 18:09:23.510645  6097 slave.cpp:2233] Master disconnected! Waiting for a new master to be elected
I0611 18:09:23.516111  6105 slave.cpp:426] Slave terminating
[       OK ] SlaveRecoveryTest/0.GCExecutor (1151 ms)

[----------] Global test environment tear-down
../../src/tests/environment.cpp:270: Failure
Failed
Tests completed with child processes remaining:
-+- 6066 /x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src/.libs/lt-mesos-tests 
 \-+- 9665 sh -c /x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src/mesos-executor 
   \-+- 9687 /x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src/.libs/lt-mesos-executor 
     \--- 9726 ()
[==========] 367 tests from 59 test cases ran. (354262 ms total)
[  PASSED  ] 367 tests.
[  FAILED  ] 0 tests, listed below:
{noformat}

I'll update the test to destroy the containers properly.

> The SlaveRecoveryTest.GCExecutor test leaks child processes.
> ------------------------------------------------------------
>
>                 Key: MESOS-1348
>                 URL: https://issues.apache.org/jira/browse/MESOS-1348
>             Project: Mesos
>          Issue Type: Bug
>          Components: test
>    Affects Versions: 0.19.0
>            Reporter: Benjamin Mahler
>            Assignee: Benjamin Mahler
>             Fix For: 0.19.0
>
>
> {noformat}
> [ RUN      ] SlaveRecoveryTest/0.GCExecutor
> Using temporary directory '/tmp/SlaveRecoveryTest_0_GCExecutor_LQg5dN'
> I0509 21:21:11.538439 11408 leveldb.cpp:174] Opened db in 105.331039ms
> I0509 21:21:11.549141 11408 leveldb.cpp:181] Compacted db in 10.684677ms
> I0509 21:21:11.549161 11408 leveldb.cpp:196] Created db iterator in 3548ns
> I0509 21:21:11.549170 11408 leveldb.cpp:202] Seeked to beginning of db in 692ns
> I0509 21:21:11.549175 11408 leveldb.cpp:271] Iterated through 0 keys in the db in 376ns
> I0509 21:21:11.549192 11408 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0509 21:21:11.549522 11453 recover.cpp:425] Starting replica recovery
> I0509 21:21:11.549705 11453 recover.cpp:451] Replica is in EMPTY status
> I0509 21:21:11.550089 11456 master.cpp:267] Master 20140509-212111-160088899-33285-11408 (vesta.apache.org) started on 67.195.138.9:33285
> I0509 21:21:11.550112 11456 master.cpp:304] Master only allowing authenticated frameworks to register
> I0509 21:21:11.550117 11456 master.cpp:309] Master only allowing authenticated slaves to register
> I0509 21:21:11.550122 11456 credentials.hpp:35] Loading credentials for authentication
> W0509 21:21:11.550164 11456 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_GCExecutor_LQg5dN/credentials': No such file or directory
> I0509 21:21:11.550330 11454 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0509 21:21:11.550456 11458 master.cpp:104] No whitelist given. Advertising offers for all slaves
> I0509 21:21:11.550462 11455 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@67.195.138.9:33285
> I0509 21:21:11.550505 11458 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0509 21:21:11.554205 11457 recover.cpp:542] Updating replica status to STARTING
> I0509 21:21:11.554463 11458 master.cpp:919] The newly elected leader is master@67.195.138.9:33285 with id 20140509-212111-160088899-33285-11408
> I0509 21:21:11.554478 11458 master.cpp:929] Elected as the leading master!
> I0509 21:21:11.554492 11458 master.cpp:750] Recovering from registrar
> I0509 21:21:11.554553 11457 registrar.cpp:313] Recovering registrar
> I0509 21:21:11.575019 11459 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 20.458205ms
> I0509 21:21:11.575052 11459 replica.cpp:320] Persisted replica status to STARTING
> I0509 21:21:11.575181 11458 recover.cpp:451] Replica is in STARTING status
> I0509 21:21:11.575682 11455 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0509 21:21:11.575809 11458 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0509 21:21:11.576114 11454 recover.cpp:542] Updating replica status to VOTING
> I0509 21:21:11.582481 11460 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 6.22694ms
> I0509 21:21:11.582502 11460 replica.cpp:320] Persisted replica status to VOTING
> I0509 21:21:11.582552 11460 recover.cpp:556] Successfully joined the Paxos group
> I0509 21:21:11.582653 11460 recover.cpp:440] Recover process terminated
> I0509 21:21:11.582799 11460 log.cpp:656] Attempting to start the writer
> I0509 21:21:11.583464 11459 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0509 21:21:11.591889 11459 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 8.412506ms
> I0509 21:21:11.591905 11459 replica.cpp:342] Persisted promised to 1
> I0509 21:21:11.592381 11453 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0509 21:21:11.592998 11457 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0509 21:21:11.599869 11457 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 6.850362ms
> I0509 21:21:11.599889 11457 replica.cpp:676] Persisted action at 0
> I0509 21:21:11.600340 11460 replica.cpp:508] Replica received write request for position 0
> I0509 21:21:11.600368 11460 leveldb.cpp:436] Reading position from leveldb took 12586ns
> I0509 21:21:11.607838 11460 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 7.458006ms
> I0509 21:21:11.607853 11460 replica.cpp:676] Persisted action at 0
> I0509 21:21:11.608006 11456 replica.cpp:655] Replica received learned notice for position 0
> I0509 21:21:11.618237 11456 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 10.214141ms
> I0509 21:21:11.618253 11456 replica.cpp:676] Persisted action at 0
> I0509 21:21:11.618262 11456 replica.cpp:661] Replica learned NOP action at position 0
> I0509 21:21:11.618461 11454 log.cpp:672] Writer started with ending position 0
> I0509 21:21:11.619083 11455 leveldb.cpp:436] Reading position from leveldb took 7410ns
> I0509 21:21:11.620265 11458 registrar.cpp:346] Successfully fetched the registry (0B)
> I0509 21:21:11.620301 11458 registrar.cpp:422] Attempting to update the 'registry'
> I0509 21:21:11.621338 11457 log.cpp:680] Attempting to append 134 bytes to the log
> I0509 21:21:11.621433 11455 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0509 21:21:11.621750 11456 replica.cpp:508] Replica received write request for position 1
> I0509 21:21:11.630163 11456 leveldb.cpp:341] Persisting action (153 bytes) to leveldb took 8.398411ms
> I0509 21:21:11.630178 11456 replica.cpp:676] Persisted action at 1
> I0509 21:21:11.630439 11455 replica.cpp:655] Replica received learned notice for position 1
> I0509 21:21:11.638134 11455 leveldb.cpp:341] Persisting action (155 bytes) to leveldb took 7.668877ms
> I0509 21:21:11.638149 11455 replica.cpp:676] Persisted action at 1
> I0509 21:21:11.638156 11455 replica.cpp:661] Replica learned APPEND action at position 1
> I0509 21:21:11.638533 11460 registrar.cpp:479] Successfully updated 'registry'
> I0509 21:21:11.638597 11460 registrar.cpp:372] Successfully recovered registrar
> I0509 21:21:11.638685 11455 log.cpp:699] Attempting to truncate the log to 1
> I0509 21:21:11.638741 11456 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0509 21:21:11.638808 11460 master.cpp:777] Recovered 0 slaves from the Registry (97B) ; allowing 10mins for slaves to re-register
> I0509 21:21:11.639102 11456 replica.cpp:508] Replica received write request for position 2
> I0509 21:21:11.647333 11408 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem
> I0509 21:21:11.649085 11455 slave.cpp:143] Slave started on 156)@67.195.138.9:33285
> I0509 21:21:11.649109 11455 credentials.hpp:35] Loading credentials for authentication
> W0509 21:21:11.649163 11455 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/credential': No such file or directory
> I0509 21:21:11.649184 11455 slave.cpp:233] Slave using credential for: test-principal
> I0509 21:21:11.649303 11455 slave.cpp:246] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0509 21:21:11.649358 11455 slave.cpp:274] Slave hostname: vesta.apache.org
> I0509 21:21:11.649366 11455 slave.cpp:275] Slave checkpoint: true
> I0509 21:21:11.649843 11455 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta'
> I0509 21:21:11.649984 11458 status_update_manager.cpp:193] Recovering status update manager
> I0509 21:21:11.650068 11457 mesos_containerizer.cpp:279] Recovering containerizer
> I0509 21:21:11.650316 11459 slave.cpp:2962] Finished recovery
> I0509 21:21:11.650678 11455 slave.cpp:527] New master detected at master@67.195.138.9:33285
> I0509 21:21:11.650710 11455 slave.cpp:587] Authenticating with master master@67.195.138.9:33285
> I0509 21:21:11.650732 11457 status_update_manager.cpp:167] New master detected at master@67.195.138.9:33285
> I0509 21:21:11.650763 11455 slave.cpp:560] Detecting new master
> I0509 21:21:11.650785 11457 authenticatee.hpp:128] Creating new client SASL connection
> I0509 21:21:11.650845 11408 sched.cpp:121] Version: 0.19.0
> I0509 21:21:11.650872 11455 master.cpp:2798] Authenticating slave(156)@67.195.138.9:33285
> I0509 21:21:11.650993 11460 authenticator.hpp:148] Creating new server SASL connection
> I0509 21:21:11.651012 11455 sched.cpp:217] New master detected at master@67.195.138.9:33285
> I0509 21:21:11.651026 11455 sched.cpp:268] Authenticating with master master@67.195.138.9:33285
> I0509 21:21:11.651057 11460 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0509 21:21:11.651075 11460 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0509 21:21:11.651108 11455 authenticatee.hpp:128] Creating new client SASL connection
> I0509 21:21:11.651141 11457 authenticator.hpp:254] Received SASL authentication start
> I0509 21:21:11.651165 11455 master.cpp:2798] Authenticating scheduler(137)@67.195.138.9:33285
> I0509 21:21:11.651180 11457 authenticator.hpp:342] Authentication requires more steps
> I0509 21:21:11.651206 11457 authenticatee.hpp:265] Received SASL authentication step
> I0509 21:21:11.651234 11455 authenticator.hpp:148] Creating new server SASL connection
> I0509 21:21:11.651244 11457 authenticator.hpp:282] Received SASL authentication step
> I0509 21:21:11.651263 11457 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0509 21:21:11.651274 11457 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0509 21:21:11.651279 11455 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0509 21:21:11.651288 11457 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0509 21:21:11.651293 11455 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0509 21:21:11.651298 11457 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0509 21:21:11.651306 11457 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:11.651311 11457 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:11.651314 11455 authenticator.hpp:254] Received SASL authentication start
> I0509 21:21:11.651324 11457 authenticator.hpp:334] Authentication success
> I0509 21:21:11.651336 11455 authenticator.hpp:342] Authentication requires more steps
> I0509 21:21:11.651347 11457 authenticatee.hpp:305] Authentication success
> I0509 21:21:11.651358 11455 master.cpp:2838] Successfully authenticated slave(156)@67.195.138.9:33285
> I0509 21:21:11.651368 11457 authenticatee.hpp:265] Received SASL authentication step
> I0509 21:21:11.651409 11455 authenticator.hpp:282] Received SASL authentication step
> I0509 21:21:11.651433 11455 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0509 21:21:11.651433 11457 slave.cpp:644] Successfully authenticated with master master@67.195.138.9:33285
> I0509 21:21:11.651440 11455 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0509 21:21:11.651449 11455 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0509 21:21:11.651458 11455 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0509 21:21:11.651463 11455 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:11.651468 11455 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:11.651470 11457 slave.cpp:873] Will retry registration in 9.45033204secs if necessary
> I0509 21:21:11.651478 11455 authenticator.hpp:334] Authentication success
> I0509 21:21:11.651520 11455 authenticatee.hpp:305] Authentication success
> I0509 21:21:11.651533 11457 master.cpp:2134] Registering slave at slave(156)@67.195.138.9:33285 (vesta.apache.org) with id 20140509-212111-160088899-33285-11408-0
> I0509 21:21:11.651569 11455 sched.cpp:342] Successfully authenticated with master master@67.195.138.9:33285
> I0509 21:21:11.651579 11455 sched.cpp:461] Sending registration request to master@67.195.138.9:33285
> I0509 21:21:11.651603 11457 master.cpp:2838] Successfully authenticated scheduler(137)@67.195.138.9:33285
> I0509 21:21:11.651687 11457 master.cpp:978] Received registration request from scheduler(137)@67.195.138.9:33285
> I0509 21:21:11.651726 11457 master.cpp:996] Registering framework 20140509-212111-160088899-33285-11408-0000 at scheduler(137)@67.195.138.9:33285
> I0509 21:21:11.651765 11455 registrar.cpp:422] Attempting to update the 'registry'
> I0509 21:21:11.651780 11457 sched.cpp:392] Framework registered with 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.651798 11457 sched.cpp:406] Scheduler::registered took 9242ns
> I0509 21:21:11.651832 11457 hierarchical_allocator_process.hpp:331] Added framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.651844 11457 hierarchical_allocator_process.hpp:725] No resources available to allocate!
> I0509 21:21:11.651850 11457 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 6108ns
> I0509 21:21:11.654062 11456 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 14.938775ms
> I0509 21:21:11.654083 11456 replica.cpp:676] Persisted action at 2
> I0509 21:21:11.654297 11456 replica.cpp:655] Replica received learned notice for position 2
> I0509 21:21:11.661996 11456 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 7.685873ms
> I0509 21:21:11.662040 11456 leveldb.cpp:399] Deleting ~1 keys from leveldb took 20377ns
> I0509 21:21:11.662052 11456 replica.cpp:676] Persisted action at 2
> I0509 21:21:11.662060 11456 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0509 21:21:11.662277 11457 log.cpp:680] Attempting to append 327 bytes to the log
> I0509 21:21:11.662328 11456 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0509 21:21:11.662644 11458 replica.cpp:508] Replica received write request for position 3
> I0509 21:21:11.669971 11458 leveldb.cpp:341] Persisting action (346 bytes) to leveldb took 7.314151ms
> I0509 21:21:11.669989 11458 replica.cpp:676] Persisted action at 3
> I0509 21:21:11.670292 11455 replica.cpp:655] Replica received learned notice for position 3
> I0509 21:21:11.677922 11455 leveldb.cpp:341] Persisting action (348 bytes) to leveldb took 7.612095ms
> I0509 21:21:11.677942 11455 replica.cpp:676] Persisted action at 3
> I0509 21:21:11.677983 11455 replica.cpp:661] Replica learned APPEND action at position 3
> I0509 21:21:11.678267 11457 registrar.cpp:479] Successfully updated 'registry'
> I0509 21:21:11.678355 11458 log.cpp:699] Attempting to truncate the log to 3
> I0509 21:21:11.678407 11460 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0509 21:21:11.678601 11454 master.cpp:2174] Registered slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org)
> I0509 21:21:11.678732 11453 replica.cpp:508] Replica received write request for position 4
> I0509 21:21:11.678714 11454 master.cpp:3283] Adding slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0509 21:21:11.678834 11457 slave.cpp:677] Registered with master master@67.195.138.9:33285; given slave ID 20140509-212111-160088899-33285-11408-0
> I0509 21:21:11.678964 11457 slave.cpp:690] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/slave.info'
> I0509 21:21:11.678977 11458 hierarchical_allocator_process.hpp:444] Added slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0509 21:21:11.679034 11458 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 to framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.679150 11458 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140509-212111-160088899-33285-11408-0 in 142987ns
> I0509 21:21:11.679208 11455 master.hpp:612] Adding offer 20140509-212111-160088899-33285-11408-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:11.679254 11455 master.cpp:2747] Sending 1 offers to framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.679355 11455 sched.cpp:529] Scheduler::resourceOffers took 19812ns
> I0509 21:21:11.680557 11454 master.hpp:622] Removing offer 20140509-212111-160088899-33285-11408-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:11.680605 11454 master.cpp:1810] Processing reply for offers: [ 20140509-212111-160088899-33285-11408-0 ] on slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org) for framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.680687 11454 master.hpp:584] Adding task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:11.680735 11454 master.cpp:2922] Launching task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org)
> I0509 21:21:11.680836 11460 slave.cpp:907] Got assigned task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 for framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.680918 11460 slave.cpp:3156] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/framework.info'
> I0509 21:21:11.681078 11460 slave.cpp:3163] Checkpointing framework pid 'scheduler(137)@67.195.138.9:33285' to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/framework.pid'
> I0509 21:21:11.681282 11460 slave.cpp:1017] Launching task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 for framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.683256 11460 slave.cpp:3478] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/executor.info'
> I0509 21:21:11.687294 11455 mesos_containerizer.cpp:523] Starting container 'a0c0c8bb-a49b-41ba-8820-303f8575dced' for executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework '20140509-212111-160088899-33285-11408-0000'
> I0509 21:21:11.687309 11460 slave.cpp:3575] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/runs/a0c0c8bb-a49b-41ba-8820-303f8575dced/tasks/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/task.info'
> I0509 21:21:11.687446 11460 slave.cpp:1127] Queuing task 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' for executor b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework '20140509-212111-160088899-33285-11408-0000
> I0509 21:21:11.687495 11460 slave.cpp:488] Successfully attached file '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/runs/a0c0c8bb-a49b-41ba-8820-303f8575dced'
> I0509 21:21:11.688833 11456 launcher.cpp:117] Forked child with pid '13390' for container 'a0c0c8bb-a49b-41ba-8820-303f8575dced'
> I0509 21:21:11.688928 11456 mesos_containerizer.cpp:746] Checkpointing executor's forked pid 13390 to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/runs/a0c0c8bb-a49b-41ba-8820-303f8575dced/pids/forked.pid'
> I0509 21:21:11.690093 11459 mesos_containerizer.cpp:623] Fetching URIs for container 'a0c0c8bb-a49b-41ba-8820-303f8575dced' using command '/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I0509 21:21:11.693989 11453 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 15.15451ms
> I0509 21:21:11.694051 11453 replica.cpp:676] Persisted action at 4
> I0509 21:21:11.694946 11458 replica.cpp:655] Replica received learned notice for position 4
> I0509 21:21:11.709843 11458 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 14.857452ms
> I0509 21:21:11.710093 11458 leveldb.cpp:399] Deleting ~2 keys from leveldb took 31693ns
> I0509 21:21:11.710160 11458 replica.cpp:676] Persisted action at 4
> I0509 21:21:11.710249 11458 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0509 21:21:12.312875 11454 slave.cpp:2299] Monitoring executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework '20140509-212111-160088899-33285-11408-0000' in container 'a0c0c8bb-a49b-41ba-8820-303f8575dced'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0509 21:21:12.344542 13412 process.cpp:1671] libprocess is initialized on 67.195.138.9:43624 for 8 cpus
> I0509 21:21:12.345546 13412 exec.cpp:131] Version: 0.19.0
> I0509 21:21:12.346982 13433 exec.cpp:181] Executor started at: executor(1)@67.195.138.9:43624 with pid 13412
> I0509 21:21:12.347771 11455 slave.cpp:1607] Got registration for executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.347853 11455 slave.cpp:1692] Checkpointing executor pid 'executor(1)@67.195.138.9:43624' to '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52/runs/a0c0c8bb-a49b-41ba-8820-303f8575dced/pids/libprocess.pid'
> I0509 21:21:12.348752 11455 slave.cpp:1726] Flushing queued task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 for executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.348840 11461 process.cpp:1098] Socket closed while receiving
> I0509 21:21:12.349097 11461 process.cpp:1098] Socket closed while receiving
> I0509 21:21:12.349094 13434 process.cpp:1037] Socket closed while receiving
> I0509 21:21:12.349144 13428 exec.cpp:205] Executor registered on slave 20140509-212111-160088899-33285-11408-0
> I0509 21:21:12.349303 13434 process.cpp:1037] Socket closed while receiving
> I0509 21:21:12.350088 13428 exec.cpp:217] Executor::registered took 126658ns
> Registered executor on vesta.apache.org
> I0509 21:21:12.350244 13428 exec.cpp:292] Executor asked to run task 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52'
> I0509 21:21:12.350296 13428 exec.cpp:301] Executor::launchTask took 38562ns
> Starting task b1cfcb14-dbd1-417a-b991-5fa6feeecb52
> Forked command at 13435
> sh -c 'sleep 1000'
> I0509 21:21:12.351841 13426 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.352150 11458 slave.cpp:1962] Handling status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 from executor(1)@67.195.138.9:43624
> I0509 21:21:12.352262 11458 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.352335 11458 status_update_manager.cpp:499] Creating StatusUpdate stream for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.352601 11458 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.442677 11458 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 to master@67.195.138.9:33285
> I0509 21:21:12.442862 11456 master.cpp:2450] Status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 from slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org)
> I0509 21:21:12.442915 11458 slave.cpp:2083] Status update manager successfully handled status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.442924 11458 slave.cpp:2089] Sending acknowledgement for status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 to executor(1)@67.195.138.9:43624
> I0509 21:21:12.443009 11460 sched.cpp:620] Scheduler::statusUpdate took 38809ns
> I0509 21:21:12.443135 11461 process.cpp:1098] Socket closed while receiving
> I0509 21:21:12.443212 13434 process.cpp:1037] Socket closed while receiving
> I0509 21:21:12.443253 11458 status_update_manager.cpp:398] Received status update acknowledgement (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.443274 11458 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: f750bad1-a42a-4d35-bb9d-386636cc76a3) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.443305 13429 exec.cpp:338] Executor received status update acknowledgement f750bad1-a42a-4d35-bb9d-386636cc76a3 for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.443379 11460 slave.cpp:416] Slave terminating
> I0509 21:21:12.443456 11460 master.cpp:688] Slave 20140509-212111-160088899-33285-11408-0 at slave(156)@67.195.138.9:33285 (vesta.apache.org) disconnected
> I0509 21:21:12.443475 11460 master.cpp:1260] Disconnecting slave 20140509-212111-160088899-33285-11408-0
> I0509 21:21:12.443608 11455 hierarchical_allocator_process.hpp:483] Slave 20140509-212111-160088899-33285-11408-0 disconnected
> I0509 21:21:12.475613 11461 process.cpp:1098] Socket closed while receiving
> I0509 21:21:12.475674 13429 exec.cpp:378] Executor asked to shutdown
> IShutting down
> 0509 21:21:12.475738 13429 exec.cpp:393] Executor::shutdown took 6056ns
> Sending SIGTERM to process tree at pid 13435
> I0509 21:21:12.475675 13434 process.cpp:1037] Socket closed while receiving
> I0509 21:21:12.475750 13430 exec.cpp:77] Scheduling shutdown of the executor
> I0509 21:21:12.475955 11408 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem
> I0509 21:21:12.477824 11459 slave.cpp:143] Slave started on 157)@67.195.138.9:33285
> I0509 21:21:12.477840 11459 credentials.hpp:35] Loading credentials for authentication
> W0509 21:21:12.477920 11459 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/credential': No such file or directory
> I0509 21:21:12.477987 11459 slave.cpp:233] Slave using credential for: test-principal
> I0509 21:21:12.478101 11459 slave.cpp:246] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0509 21:21:12.478158 11459 slave.cpp:274] Slave hostname: vesta.apache.org
> I0509 21:21:12.478166 11459 slave.cpp:275] Slave checkpoint: true
> I0509 21:21:12.478714 11455 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta'
> W0509 21:21:12.479399 11455 state.cpp:331] Failed to find the latest run of executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.479683 11459 slave.cpp:3030] Recovering framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.479702 11459 slave.cpp:3328] Recovering executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000
> W0509 21:21:12.479709 11459 slave.cpp:3334] Skipping recovery of executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000 because its latest run or executor info cannot be recovered
> I0509 21:21:12.479763 11459 slave.cpp:2571] Cleaning up framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.479765 11455 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52' for gc 6.99998287350815days in the future
> I0509 21:21:12.479816 11455 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52' for gc 6.99998287321778days in the future
> I0509 21:21:12.479846 11455 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000' for gc 6.99999444686518days in the future
> I0509 21:21:12.479874 11455 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000' for gc 6.99999444659556days in the future
> I0509 21:21:12.479904 11455 status_update_manager.cpp:282] Closing status update streams for framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.480051 11456 status_update_manager.cpp:193] Recovering status update manager
> I0509 21:21:12.480062 11456 status_update_manager.cpp:201] Recovering executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000
> W0509 21:21:12.480068 11456 status_update_manager.cpp:205] Skipping recovering updates of executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000 because its info cannot be recovered
> I0509 21:21:12.480387 11453 mesos_containerizer.cpp:279] Recovering containerizer
> W0509 21:21:12.480403 11453 mesos_containerizer.cpp:287] Skipping recovery of executor 'b1cfcb14-dbd1-417a-b991-5fa6feeecb52' of framework 20140509-212111-160088899-33285-11408-0000 because its info could not be recovered
> I0509 21:21:12.480837 11458 slave.cpp:2962] Finished recovery
> I0509 21:21:12.481205 11460 slave.cpp:527] New master detected at master@67.195.138.9:33285
> I0509 21:21:12.481232 11460 slave.cpp:587] Authenticating with master master@67.195.138.9:33285
> I0509 21:21:12.481286 11453 status_update_manager.cpp:167] New master detected at master@67.195.138.9:33285
> I0509 21:21:12.481298 11460 slave.cpp:560] Detecting new master
> I0509 21:21:12.481358 11453 authenticatee.hpp:128] Creating new client SASL connection
> I0509 21:21:12.481498 11456 master.cpp:2798] Authenticating slave(157)@67.195.138.9:33285
> I0509 21:21:12.481632 11453 authenticator.hpp:148] Creating new server SASL connection
> I0509 21:21:12.481729 11455 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0509 21:21:12.481752 11455 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0509 21:21:12.481806 11455 authenticator.hpp:254] Received SASL authentication start
> I0509 21:21:12.481853 11455 authenticator.hpp:342] Authentication requires more steps
> I0509 21:21:12.481880 11455 authenticatee.hpp:265] Received SASL authentication step
> I0509 21:21:12.481935 11455 authenticator.hpp:282] Received SASL authentication step
> I0509 21:21:12.481966 11455 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0509 21:21:12.481973 11455 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0509 21:21:12.481984 11455 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0509 21:21:12.481994 11455 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0509 21:21:12.482002 11455 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:12.482007 11455 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0509 21:21:12.482017 11455 authenticator.hpp:334] Authentication success
> I0509 21:21:12.482056 11453 authenticatee.hpp:305] Authentication success
> I0509 21:21:12.482066 11455 master.cpp:2838] Successfully authenticated slave(157)@67.195.138.9:33285
> I0509 21:21:12.482174 11453 slave.cpp:644] Successfully authenticated with master master@67.195.138.9:33285
> I0509 21:21:12.482211 11453 slave.cpp:833] Reregistering completed framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.482260 11453 slave.cpp:873] Will retry registration in 6.836005163secs if necessary
> W0509 21:21:12.482391 11457 master.cpp:2248] Slave at slave(157)@67.195.138.9:33285 (vesta.apache.org) is being allowed to re-register with an already in use id (20140509-212111-160088899-33285-11408-0)
> W0509 21:21:12.482426 11457 master.cpp:2966] Sending TASK_LOST for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 unknown to the slave 20140509-212111-160088899-33285-11408-0 at slave(157)@67.195.138.9:33285 (vesta.apache.org)
> I0509 21:21:12.482434 11453 slave.cpp:727] Re-registered with master master@67.195.138.9:33285
> I0509 21:21:12.483248 11457 master.cpp:2450] Status update TASK_LOST (UUID: e2dc8b90-824a-4bb7-8caa-16345becb95b) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 from slave 20140509-212111-160088899-33285-11408-0 at slave(157)@67.195.138.9:33285 (vesta.apache.org)
> I0509 21:21:12.483307 11456 sched.cpp:620] Scheduler::statusUpdate took 7885ns
> I0509 21:21:12.483317 11457 master.hpp:602] Removing task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:12.483492 11456 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140509-212111-160088899-33285-11408-0 from framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.483525 11456 hierarchical_allocator_process.hpp:497] Slave 20140509-212111-160088899-33285-11408-0 reconnected
> I0509 21:21:12.491060 11457 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 to framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.491248 11457 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 242634ns
> I0509 21:21:12.491304 11456 master.hpp:612] Adding offer 20140509-212111-160088899-33285-11408-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:12.491369 11456 master.cpp:2747] Sending 1 offers to framework 20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.491544 11453 sched.cpp:529] Scheduler::resourceOffers took 18763ns
> Killing the following process trees:
> [ 
> -+- 13435 sh -c sleep 1000 
>  \--- 13436 sleep 1000 
> ]
> I0509 21:21:12.511373 11460 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 21442ns
> I0509 21:21:12.511620 11459 master.cpp:104] No whitelist given. Advertising offers for all slaves
> I0509 21:21:12.511742 11457 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52
> I0509 21:21:12.511713 11455 slave.cpp:2817] Current usage 40.87%. Max allowed age: 3.438910272322743days
> I0509 21:21:12.511934 11457 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52'
> I0509 21:21:12.511989 11457 gc.cpp:167] Pruning directories with remaining removal time 0ns
> I0509 21:21:12.512001 11457 gc.cpp:167] Pruning directories with remaining removal time 0ns
> I0509 21:21:12.512008 11457 gc.cpp:167] Pruning directories with remaining removal time 0ns
> I0509 21:21:12.512025 11457 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52
> I0509 21:21:12.512311 11457 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000/executors/b1cfcb14-dbd1-417a-b991-5fa6feeecb52'
> I0509 21:21:12.512347 11457 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
> I0509 21:21:12.512370 11457 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.512416 11457 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000'
> I0509 21:21:12.512449 11457 gc.cpp:134] Deleting /tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000
> I0509 21:21:12.512547 11457 gc.cpp:143] Deleted '/tmp/SlaveRecoveryTest_0_GCExecutor_vX3tsQ/meta/slaves/20140509-212111-160088899-33285-11408-0/frameworks/20140509-212111-160088899-33285-11408-0000'
> I0509 21:21:12.512574 11457 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
> I0509 21:21:12.512588 11457 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
> I0509 21:21:12.512603 11457 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
> I0509 21:21:12.531309 11458 sched.cpp:731] Stopping framework '20140509-212111-160088899-33285-11408-0000'
> I0509 21:21:12.531358 11408 master.cpp:550] Master terminating
> I0509 21:21:12.531482 11408 master.hpp:622] Removing offer 20140509-212111-160088899-33285-11408-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212111-160088899-33285-11408-0 (vesta.apache.org)
> I0509 21:21:12.531733 11460 slave.cpp:2168] master@67.195.138.9:33285 exited
> W0509 21:21:12.531754 11460 slave.cpp:2171] Master disconnected! Waiting for a new master to be elected
> I0509 21:21:12.533133 11408 slave.cpp:416] Slave terminating
> [       OK ] SlaveRecoveryTest/0.GCExecutor (1102 ms)
> [----------] 24 tests from SlaveRecoveryTest/0 (63658 ms total)
> {noformat}
> Test tear down:
> {noformat}
> [----------] Global test environment tear-down
> ../../src/tests/environment.cpp:258: Failure
> Failed
> Tests completed with child processes remaining:
> -+- 11408 /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/.libs/lt-mesos-tests 
>  \-+- 13390 sh -c /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-executor 
>    \--- 13412 /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/.libs/lt-mesos-executor 
> [==========] 279 tests from 45 test cases ran. (171208 ms total)
> [  PASSED  ] 279 tests.
> [  FAILED  ] 0 tests, listed below:
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.2#6252)