You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Cody Maloney (JIRA)" <ji...@apache.org> on 2014/12/04 22:29:15 UTC
[jira] [Updated] (MESOS-1609) SlaveRecoveryTest/0.MultipleSlaves is
flaky: runs forever.
[ https://issues.apache.org/jira/browse/MESOS-1609?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Cody Maloney updated MESOS-1609:
--------------------------------
Labels: flaky (was: )
> SlaveRecoveryTest/0.MultipleSlaves is flaky: runs forever.
> ----------------------------------------------------------
>
> Key: MESOS-1609
> URL: https://issues.apache.org/jira/browse/MESOS-1609
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Labels: flaky
>
> Looks like the slaves are not finishing recovery when they restart.
> {noformat: title=flaky run}
> [ RUN ] SlaveRecoveryTest/0.MultipleSlaves
> Using temporary directory '/tmp/SlaveRecoveryTest_0_MultipleSlaves_Sv71KW'
> I0716 03:24:28.769244 2209 leveldb.cpp:176] Opened db in 831176ns
> I0716 03:24:28.769795 2209 leveldb.cpp:183] Compacted db in 540041ns
> I0716 03:24:28.769816 2209 leveldb.cpp:198] Created db iterator in 8256ns
> I0716 03:24:28.769825 2209 leveldb.cpp:204] Seeked to beginning of db in 4387ns
> I0716 03:24:28.769831 2209 leveldb.cpp:273] Iterated through 0 keys in the db in 3836ns
> I0716 03:24:28.769845 2209 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0716 03:24:28.770287 2230 recover.cpp:425] Starting replica recovery
> I0716 03:24:28.771174 2234 recover.cpp:451] Replica is in EMPTY status
> I0716 03:24:28.771574 2230 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0716 03:24:28.771625 2230 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0716 03:24:28.771694 2230 recover.cpp:542] Updating replica status to STARTING
> I0716 03:24:28.771774 2230 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 44756ns
> I0716 03:24:28.771788 2230 replica.cpp:320] Persisted replica status to STARTING
> I0716 03:24:28.771822 2230 recover.cpp:451] Replica is in STARTING status
> I0716 03:24:28.772707 2230 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0716 03:24:28.773192 2230 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0716 03:24:28.773589 2230 recover.cpp:542] Updating replica status to VOTING
> I0716 03:24:28.773643 2230 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 23615ns
> I0716 03:24:28.773654 2230 replica.cpp:320] Persisted replica status to VOTING
> I0716 03:24:28.773674 2230 recover.cpp:556] Successfully joined the Paxos group
> I0716 03:24:28.773725 2230 recover.cpp:440] Recover process terminated
> I0716 03:24:28.775101 2229 master.cpp:288] Master 20140716-032428-2272962752-50601-2209 (fedora-19) started on 192.168.122.135:50601
> I0716 03:24:28.775130 2229 master.cpp:325] Master only allowing authenticated frameworks to register
> I0716 03:24:28.775137 2229 master.cpp:330] Master only allowing authenticated slaves to register
> I0716 03:24:28.775145 2229 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_Sv71KW/credentials'
> I0716 03:24:28.775265 2229 master.cpp:359] Authorization enabled
> I0716 03:24:28.775807 2233 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@192.168.122.135:50601
> I0716 03:24:28.775843 2233 master.cpp:122] No whitelist given. Advertising offers for all slaves
> I0716 03:24:28.776481 2229 master.cpp:1128] The newly elected leader is master@192.168.122.135:50601 with id 20140716-032428-2272962752-50601-2209
> I0716 03:24:28.776500 2229 master.cpp:1141] Elected as the leading master!
> I0716 03:24:28.776507 2229 master.cpp:959] Recovering from registrar
> I0716 03:24:28.776571 2229 registrar.cpp:313] Recovering registrar
> I0716 03:24:28.776954 2229 log.cpp:656] Attempting to start the writer
> I0716 03:24:28.777779 2234 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0716 03:24:28.777814 2234 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 23559ns
> I0716 03:24:28.777825 2234 replica.cpp:342] Persisted promised to 1
> I0716 03:24:28.777968 2234 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0716 03:24:28.778609 2234 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0716 03:24:28.778645 2234 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 25492ns
> I0716 03:24:28.778657 2234 replica.cpp:676] Persisted action at 0
> I0716 03:24:28.778909 2234 replica.cpp:508] Replica received write request for position 0
> I0716 03:24:28.778936 2234 leveldb.cpp:438] Reading position from leveldb took 16938ns
> I0716 03:24:28.778962 2234 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 18022ns
> I0716 03:24:28.778971 2234 replica.cpp:676] Persisted action at 0
> I0716 03:24:28.779124 2234 replica.cpp:655] Replica received learned notice for position 0
> I0716 03:24:28.779155 2234 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 20711ns
> I0716 03:24:28.779165 2234 replica.cpp:676] Persisted action at 0
> I0716 03:24:28.779171 2234 replica.cpp:661] Replica learned NOP action at position 0
> I0716 03:24:28.779337 2234 log.cpp:672] Writer started with ending position 0
> I0716 03:24:28.779575 2234 leveldb.cpp:438] Reading position from leveldb took 20962ns
> I0716 03:24:28.780519 2234 registrar.cpp:346] Successfully fetched the registry (0B)
> I0716 03:24:28.780541 2234 registrar.cpp:422] Attempting to update the 'registry'
> I0716 03:24:28.782104 2229 log.cpp:680] Attempting to append 130 bytes to the log
> I0716 03:24:28.782156 2229 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0716 03:24:28.782312 2229 replica.cpp:508] Replica received write request for position 1
> I0716 03:24:28.782347 2229 leveldb.cpp:343] Persisting action (149 bytes) to leveldb took 25633ns
> I0716 03:24:28.782359 2229 replica.cpp:676] Persisted action at 1
> I0716 03:24:28.782502 2229 replica.cpp:655] Replica received learned notice for position 1
> I0716 03:24:28.782533 2229 leveldb.cpp:343] Persisting action (151 bytes) to leveldb took 21987ns
> I0716 03:24:28.782543 2229 replica.cpp:676] Persisted action at 1
> I0716 03:24:28.782552 2229 replica.cpp:661] Replica learned APPEND action at position 1
> I0716 03:24:28.782773 2229 registrar.cpp:479] Successfully updated 'registry'
> I0716 03:24:28.782821 2229 registrar.cpp:372] Successfully recovered registrar
> I0716 03:24:28.782857 2229 log.cpp:699] Attempting to truncate the log to 1
> I0716 03:24:28.782917 2229 master.cpp:986] Recovered 0 slaves from the Registry (94B) ; allowing 10mins for slaves to re-register
> I0716 03:24:28.783289 2229 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0716 03:24:28.783627 2229 replica.cpp:508] Replica received write request for position 2
> I0716 03:24:28.783660 2229 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 22920ns
> I0716 03:24:28.783671 2229 replica.cpp:676] Persisted action at 2
> I0716 03:24:28.783802 2229 replica.cpp:655] Replica received learned notice for position 2
> I0716 03:24:28.783830 2229 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 20166ns
> I0716 03:24:28.783845 2229 leveldb.cpp:401] Deleting ~1 keys from leveldb took 9684ns
> I0716 03:24:28.783854 2229 replica.cpp:676] Persisted action at 2
> I0716 03:24:28.783860 2229 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0716 03:24:28.797114 2209 sched.cpp:139] Version: 0.20.0
> I0716 03:24:28.797502 2209 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0716 03:24:28.798143 2229 sched.cpp:235] New master detected at master@192.168.122.135:50601
> I0716 03:24:28.798166 2229 sched.cpp:285] Authenticating with master master@192.168.122.135:50601
> I0716 03:24:28.798230 2229 authenticatee.hpp:128] Creating new client SASL connection
> I0716 03:24:28.799192 2229 master.cpp:3512] Authenticating scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601
> I0716 03:24:28.799271 2229 authenticator.hpp:156] Creating new server SASL connection
> I0716 03:24:28.799911 2229 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 03:24:28.799934 2229 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 03:24:28.799958 2229 authenticator.hpp:262] Received SASL authentication start
> I0716 03:24:28.799989 2229 authenticator.hpp:384] Authentication requires more steps
> I0716 03:24:28.800379 2229 authenticatee.hpp:265] Received SASL authentication step
> I0716 03:24:28.800612 2229 authenticator.hpp:290] Received SASL authentication step
> I0716 03:24:28.800634 2229 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 03:24:28.800643 2229 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0716 03:24:28.800653 2229 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 03:24:28.800662 2229 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 03:24:28.800669 2229 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:28.800674 2229 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:28.800714 2229 authenticator.hpp:376] Authentication success
> I0716 03:24:28.800747 2229 authenticatee.hpp:305] Authentication success
> I0716 03:24:28.800768 2229 master.cpp:3552] Successfully authenticated principal 'test-principal' at scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601
> I0716 03:24:28.800830 2229 sched.cpp:359] Successfully authenticated with master master@192.168.122.135:50601
> I0716 03:24:28.800844 2229 sched.cpp:478] Sending registration request to master@192.168.122.135:50601
> I0716 03:24:28.800879 2229 master.cpp:1247] Received registration request from scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601
> I0716 03:24:28.800892 2229 master.cpp:1207] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0716 03:24:28.801012 2229 master.cpp:1306] Registering framework 20140716-032428-2272962752-50601-2209-0000 at scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601
> I0716 03:24:28.801290 2229 sched.cpp:409] Framework registered with 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.801311 2229 sched.cpp:423] Scheduler::registered took 11638ns
> I0716 03:24:28.801338 2229 hierarchical_allocator_process.hpp:331] Added framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.801348 2229 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0716 03:24:28.801354 2229 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 9964ns
> I0716 03:24:28.802470 2228 slave.cpp:168] Slave started on 117)@192.168.122.135:50601
> I0716 03:24:28.802500 2228 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/credential'
> I0716 03:24:28.802573 2228 slave.cpp:266] Slave using credential for: test-principal
> I0716 03:24:28.802646 2228 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:28.803411 2228 slave.cpp:324] Slave hostname: fedora-19
> I0716 03:24:28.803426 2228 slave.cpp:325] Slave checkpoint: true
> I0716 03:24:28.803720 2228 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta'
> I0716 03:24:28.803803 2228 status_update_manager.cpp:193] Recovering status update manager
> I0716 03:24:28.803846 2228 containerizer.cpp:287] Recovering containerizer
> I0716 03:24:28.804201 2228 slave.cpp:3127] Finished recovery
> I0716 03:24:28.804844 2228 slave.cpp:600] New master detected at master@192.168.122.135:50601
> I0716 03:24:28.804882 2228 slave.cpp:676] Authenticating with master master@192.168.122.135:50601
> I0716 03:24:28.804919 2228 slave.cpp:649] Detecting new master
> I0716 03:24:28.804954 2228 status_update_manager.cpp:167] New master detected at master@192.168.122.135:50601
> I0716 03:24:28.804978 2228 authenticatee.hpp:128] Creating new client SASL connection
> I0716 03:24:28.805625 2228 master.cpp:3512] Authenticating slave(117)@192.168.122.135:50601
> I0716 03:24:28.805712 2228 authenticator.hpp:156] Creating new server SASL connection
> I0716 03:24:28.806212 2228 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 03:24:28.806236 2228 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 03:24:28.806259 2228 authenticator.hpp:262] Received SASL authentication start
> I0716 03:24:28.806289 2228 authenticator.hpp:384] Authentication requires more steps
> I0716 03:24:28.806313 2228 authenticatee.hpp:265] Received SASL authentication step
> I0716 03:24:28.806344 2228 authenticator.hpp:290] Received SASL authentication step
> I0716 03:24:28.806359 2228 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 03:24:28.806365 2228 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0716 03:24:28.806375 2228 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 03:24:28.806385 2228 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 03:24:28.806391 2228 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:28.806562 2228 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:28.806586 2228 authenticator.hpp:376] Authentication success
> I0716 03:24:28.806769 2227 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(117)@192.168.122.135:50601
> I0716 03:24:28.806916 2228 authenticatee.hpp:305] Authentication success
> I0716 03:24:28.807003 2228 slave.cpp:733] Successfully authenticated with master master@192.168.122.135:50601
> I0716 03:24:28.807188 2228 slave.cpp:971] Will retry registration in 18.780032ms if necessary
> I0716 03:24:28.807252 2228 master.cpp:2789] Registering slave at slave(117)@192.168.122.135:50601 (fedora-19) with id 20140716-032428-2272962752-50601-2209-0
> I0716 03:24:28.807348 2228 registrar.cpp:422] Attempting to update the 'registry'
> I0716 03:24:28.808616 2228 log.cpp:680] Attempting to append 310 bytes to the log
> I0716 03:24:28.808657 2228 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0716 03:24:28.808830 2228 replica.cpp:508] Replica received write request for position 3
> I0716 03:24:28.808869 2228 leveldb.cpp:343] Persisting action (329 bytes) to leveldb took 28326ns
> I0716 03:24:28.808881 2228 replica.cpp:676] Persisted action at 3
> I0716 03:24:28.811003 2234 replica.cpp:655] Replica received learned notice for position 3
> I0716 03:24:28.811066 2234 leveldb.cpp:343] Persisting action (331 bytes) to leveldb took 54361ns
> I0716 03:24:28.811081 2234 replica.cpp:676] Persisted action at 3
> I0716 03:24:28.811089 2234 replica.cpp:661] Replica learned APPEND action at position 3
> I0716 03:24:28.811337 2234 registrar.cpp:479] Successfully updated 'registry'
> I0716 03:24:28.811398 2234 log.cpp:699] Attempting to truncate the log to 3
> I0716 03:24:28.811437 2234 master.cpp:2829] Registered slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:28.811450 2234 master.cpp:3980] Adding slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:28.811547 2234 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0716 03:24:28.812127 2234 slave.cpp:767] Registered with master master@192.168.122.135:50601; given slave ID 20140716-032428-2272962752-50601-2209-0
> I0716 03:24:28.812352 2234 slave.cpp:780] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/slave.info'
> I0716 03:24:28.812481 2234 slave.cpp:2324] Received ping from slave-observer(102)@192.168.122.135:50601
> I0716 03:24:28.812731 2232 hierarchical_allocator_process.hpp:444] Added slave 20140716-032428-2272962752-50601-2209-0 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0716 03:24:28.812786 2232 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-0 to framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.812868 2232 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140716-032428-2272962752-50601-2209-0 in 109933ns
> I0716 03:24:28.812917 2232 master.hpp:802] Adding offer 20140716-032428-2272962752-50601-2209-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-0 (fedora-19)
> I0716 03:24:28.812954 2232 master.cpp:3459] Sending 1 offers to framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.813278 2230 replica.cpp:508] Replica received write request for position 4
> I0716 03:24:28.813313 2230 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 24446ns
> I0716 03:24:28.813324 2230 replica.cpp:676] Persisted action at 4
> I0716 03:24:28.813495 2230 replica.cpp:655] Replica received learned notice for position 4
> I0716 03:24:28.813526 2230 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 21220ns
> I0716 03:24:28.813542 2230 leveldb.cpp:401] Deleting ~2 keys from leveldb took 11604ns
> I0716 03:24:28.813551 2230 replica.cpp:676] Persisted action at 4
> I0716 03:24:28.813559 2230 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0716 03:24:28.813714 2232 sched.cpp:546] Scheduler::resourceOffers took 46628ns
> I0716 03:24:28.815564 2232 master.hpp:812] Removing offer 20140716-032428-2272962752-50601-2209-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-0 (fedora-19)
> I0716 03:24:28.815614 2232 master.cpp:2133] Processing reply for offers: [ 20140716-032428-2272962752-50601-2209-0 ] on slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19) for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.815645 2232 master.cpp:2219] Authorizing framework principal 'test-principal' to launch task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 as user 'jenkins'
> I0716 03:24:28.815860 2232 master.hpp:774] Adding task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-0 (fedora-19)
> I0716 03:24:28.815894 2232 master.cpp:2285] Launching task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:28.815999 2232 slave.cpp:1002] Got assigned task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.816216 2232 slave.cpp:3399] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/framework.info'
> I0716 03:24:28.816789 2232 slave.cpp:3406] Checkpointing framework pid 'scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/framework.pid'
> I0716 03:24:28.817208 2232 slave.cpp:1112] Launching task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.818892 2232 slave.cpp:3721] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/executor.info'
> I0716 03:24:28.819599 2232 slave.cpp:3836] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/runs/5f163b4b-d329-4a6a-8c88-07d66a9e827c/tasks/89a4508d-6d24-42de-b0e3-56c95aad5ab7/task.info'
> I0716 03:24:28.819787 2232 slave.cpp:1222] Queuing task '89a4508d-6d24-42de-b0e3-56c95aad5ab7' for executor 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework '20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:28.819903 2232 containerizer.cpp:427] Starting container '5f163b4b-d329-4a6a-8c88-07d66a9e827c' for executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework '20140716-032428-2272962752-50601-2209-0000'
> I0716 03:24:28.821275 2231 slave.cpp:561] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/runs/5f163b4b-d329-4a6a-8c88-07d66a9e827c'
> I0716 03:24:28.825498 2232 launcher.cpp:137] Forked child with pid '4999' for container '5f163b4b-d329-4a6a-8c88-07d66a9e827c'
> I0716 03:24:28.825628 2232 containerizer.cpp:705] Checkpointing executor's forked pid 4999 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/runs/5f163b4b-d329-4a6a-8c88-07d66a9e827c/pids/forked.pid'
> I0716 03:24:28.826994 2232 containerizer.cpp:537] Fetching URIs for container '5f163b4b-d329-4a6a-8c88-07d66a9e827c' using command '/var/jenkins/workspace/mesos-fedora-19-clang/src/mesos-fetcher'
> I0716 03:24:29.759738 2233 slave.cpp:2469] Monitoring executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework '20140716-032428-2272962752-50601-2209-0000' in container '5f163b4b-d329-4a6a-8c88-07d66a9e827c'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0716 03:24:29.763543 4999 process.cpp:1671] libprocess is initialized on 192.168.122.135:44671 for 8 cpus
> I0716 03:24:29.766860 4999 exec.cpp:131] Version: 0.20.0
> I0716 03:24:29.767658 5050 exec.cpp:181] Executor started at: executor(1)@192.168.122.135:44671 with pid 4999
> I0716 03:24:29.768590 2233 slave.cpp:1733] Got registration for executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.768642 2233 slave.cpp:1818] Checkpointing executor pid 'executor(1)@192.168.122.135:44671' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/runs/5f163b4b-d329-4a6a-8c88-07d66a9e827c/pids/libprocess.pid'
> I0716 03:24:29.769224 2233 slave.cpp:1852] Flushing queued task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 for executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.769821 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:29.770511 5050 exec.cpp:205] Executor registered on slave 20140716-032428-2272962752-50601-2209-0
> IRegistered executor on fedora-19
> 0716 03:24:29.771842 5050 exec.cpp:217] Executor::registered took 112331ns
> I0716 03:24:29.772783 5043 exec.cpp:292] Executor asked to run task '89a4508d-6d24-42de-b0e3-56c95aad5ab7'
> IStarting task 89a4508d-6d24-42de-b0e3-56c95aad5ab7
> 0716 03:24:29.773196 5043 exec.cpp:301] Executor::launchTask took 68223ns
> I0716 03:24:29.774260 5051 process.cpp:1037] Socket closed while receiving
> I0716 03:24:29.776185 2230 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 103801ns
> sh -c 'sleep 1000'
> Forked command at 5052
> I0716 03:24:29.783259 5048 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.783895 2230 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 from executor(1)@192.168.122.135:44671
> I0716 03:24:29.784041 2230 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.784064 2230 status_update_manager.cpp:499] Creating StatusUpdate stream for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.784314 2230 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.784428 2230 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 to master@192.168.122.135:50601
> I0716 03:24:29.784579 2230 master.cpp:3120] Status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 from slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:29.784625 2230 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.784636 2230 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 to executor(1)@192.168.122.135:44671
> I0716 03:24:29.784878 2230 sched.cpp:637] Scheduler::statusUpdate took 22964ns
> I0716 03:24:29.784952 2230 master.cpp:2639] Forwarding status update acknowledgement f92d9fe0-117c-4732-a1ec-e16b5fad4ec8 for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 to slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:29.785166 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:29.785584 2227 status_update_manager.cpp:398] Received status update acknowledgement (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.785624 2227 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.786669 2209 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0716 03:24:29.788211 5049 exec.cpp:338] Executor received status update acknowledgement f92d9fe0-117c-4732-a1ec-e16b5fad4ec8 for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.788336 5051 process.cpp:1037] Socket closed while receiving
> I0716 03:24:29.789064 2230 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: f92d9fe0-117c-4732-a1ec-e16b5fad4ec8) for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.792541 2229 slave.cpp:168] Slave started on 118)@192.168.122.135:50601
> I0716 03:24:29.792582 2229 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/credential'
> I0716 03:24:29.792668 2229 slave.cpp:266] Slave using credential for: test-principal
> I0716 03:24:29.792763 2229 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:29.793251 2229 slave.cpp:324] Slave hostname: fedora-19
> I0716 03:24:29.793267 2229 slave.cpp:325] Slave checkpoint: true
> I0716 03:24:29.793665 2229 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta'
> I0716 03:24:29.793786 2229 status_update_manager.cpp:193] Recovering status update manager
> I0716 03:24:29.793833 2229 containerizer.cpp:287] Recovering containerizer
> I0716 03:24:29.794239 2229 slave.cpp:3127] Finished recovery
> I0716 03:24:29.794517 2229 slave.cpp:600] New master detected at master@192.168.122.135:50601
> I0716 03:24:29.794549 2229 slave.cpp:676] Authenticating with master master@192.168.122.135:50601
> I0716 03:24:29.794611 2229 slave.cpp:649] Detecting new master
> I0716 03:24:29.794647 2229 status_update_manager.cpp:167] New master detected at master@192.168.122.135:50601
> I0716 03:24:29.794692 2229 authenticatee.hpp:128] Creating new client SASL connection
> I0716 03:24:29.795361 2232 master.cpp:3512] Authenticating slave(118)@192.168.122.135:50601
> I0716 03:24:29.795475 2232 authenticator.hpp:156] Creating new server SASL connection
> I0716 03:24:29.795953 2229 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 03:24:29.795981 2229 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 03:24:29.796442 2228 authenticator.hpp:262] Received SASL authentication start
> I0716 03:24:29.796488 2228 authenticator.hpp:384] Authentication requires more steps
> I0716 03:24:29.796690 2229 authenticatee.hpp:265] Received SASL authentication step
> I0716 03:24:29.796946 2229 authenticator.hpp:290] Received SASL authentication step
> I0716 03:24:29.796999 2229 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 03:24:29.797009 2229 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0716 03:24:29.797490 2229 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 03:24:29.797507 2229 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 03:24:29.797514 2229 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:29.797520 2229 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 03:24:29.797533 2229 authenticator.hpp:376] Authentication success
> I0716 03:24:29.797920 2227 authenticatee.hpp:305] Authentication success
> I0716 03:24:29.800551 2227 slave.cpp:733] Successfully authenticated with master master@192.168.122.135:50601
> I0716 03:24:29.800946 2227 slave.cpp:971] Will retry registration in 18.508038ms if necessary
> I0716 03:24:29.801285 2230 master.cpp:2731] Queuing up registration request from slave(118)@192.168.122.135:50601 because authentication is still in progress
> I0716 03:24:29.801424 2230 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(118)@192.168.122.135:50601
> I0716 03:24:29.801543 2230 master.cpp:2789] Registering slave at slave(118)@192.168.122.135:50601 (fedora-19) with id 20140716-032428-2272962752-50601-2209-1
> I0716 03:24:29.801669 2230 registrar.cpp:422] Attempting to update the 'registry'
> I0716 03:24:29.802762 2230 log.cpp:680] Attempting to append 484 bytes to the log
> I0716 03:24:29.802834 2230 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0716 03:24:29.803553 2234 replica.cpp:508] Replica received write request for position 5
> I0716 03:24:29.803647 2234 leveldb.cpp:343] Persisting action (503 bytes) to leveldb took 65787ns
> I0716 03:24:29.803661 2234 replica.cpp:676] Persisted action at 5
> I0716 03:24:29.804224 2228 replica.cpp:655] Replica received learned notice for position 5
> I0716 03:24:29.804278 2228 leveldb.cpp:343] Persisting action (505 bytes) to leveldb took 42666ns
> I0716 03:24:29.804293 2228 replica.cpp:676] Persisted action at 5
> I0716 03:24:29.804301 2228 replica.cpp:661] Replica learned APPEND action at position 5
> I0716 03:24:29.808151 2233 registrar.cpp:479] Successfully updated 'registry'
> I0716 03:24:29.808238 2233 master.cpp:2829] Registered slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:29.808254 2233 master.cpp:3980] Adding slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:29.808368 2233 slave.cpp:767] Registered with master master@192.168.122.135:50601; given slave ID 20140716-032428-2272962752-50601-2209-1
> I0716 03:24:29.808548 2233 slave.cpp:780] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/slave.info'
> I0716 03:24:29.808720 2233 hierarchical_allocator_process.hpp:444] Added slave 20140716-032428-2272962752-50601-2209-1 (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0716 03:24:29.808778 2233 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-1 to framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.808886 2233 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140716-032428-2272962752-50601-2209-1 in 139778ns
> I0716 03:24:29.808913 2233 slave.cpp:2324] Received ping from slave-observer(103)@192.168.122.135:50601
> I0716 03:24:29.808984 2233 master.hpp:802] Adding offer 20140716-032428-2272962752-50601-2209-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-1 (fedora-19)
> I0716 03:24:29.809571 2233 master.cpp:3459] Sending 1 offers to framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.809923 2232 sched.cpp:546] Scheduler::resourceOffers took 62563ns
> I0716 03:24:29.811416 2231 master.hpp:812] Removing offer 20140716-032428-2272962752-50601-2209-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-1 (fedora-19)
> I0716 03:24:29.811475 2231 master.cpp:2133] Processing reply for offers: [ 20140716-032428-2272962752-50601-2209-1 ] on slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19) for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.811524 2231 master.cpp:2219] Authorizing framework principal 'test-principal' to launch task adfda8a6-0064-41bc-afa8-74fa1f5b556c as user 'jenkins'
> I0716 03:24:29.811816 2231 master.hpp:774] Adding task adfda8a6-0064-41bc-afa8-74fa1f5b556c with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-1 (fedora-19)
> I0716 03:24:29.811854 2231 master.cpp:2285] Launching task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:29.811964 2231 slave.cpp:1002] Got assigned task adfda8a6-0064-41bc-afa8-74fa1f5b556c for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.812091 2231 slave.cpp:3399] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/framework.info'
> I0716 03:24:29.812280 2231 slave.cpp:3406] Checkpointing framework pid 'scheduler-8406a7e0-0c1f-4dce-8c18-2c2625285966@192.168.122.135:50601' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/framework.pid'
> I0716 03:24:29.812551 2231 slave.cpp:1112] Launching task adfda8a6-0064-41bc-afa8-74fa1f5b556c for framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.814190 2231 slave.cpp:3721] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/executor.info'
> I0716 03:24:29.815233 2233 log.cpp:699] Attempting to truncate the log to 5
> I0716 03:24:29.815289 2233 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0716 03:24:29.815454 2233 replica.cpp:508] Replica received write request for position 6
> I0716 03:24:29.815489 2233 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 25621ns
> I0716 03:24:29.815500 2233 replica.cpp:676] Persisted action at 6
> I0716 03:24:29.815644 2233 replica.cpp:655] Replica received learned notice for position 6
> I0716 03:24:29.815675 2233 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 21294ns
> I0716 03:24:29.815691 2233 leveldb.cpp:401] Deleting ~2 keys from leveldb took 11830ns
> I0716 03:24:29.815701 2233 replica.cpp:676] Persisted action at 6
> I0716 03:24:29.815707 2233 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0716 03:24:29.817129 2234 containerizer.cpp:427] Starting container '50b2896d-0a67-4f83-9a73-f7fa7995081f' for executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework '20140716-032428-2272962752-50601-2209-0000'
> I0716 03:24:29.819866 2234 launcher.cpp:137] Forked child with pid '5053' for container '50b2896d-0a67-4f83-9a73-f7fa7995081f'
> I0716 03:24:29.820129 2234 containerizer.cpp:705] Checkpointing executor's forked pid 5053 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/runs/50b2896d-0a67-4f83-9a73-f7fa7995081f/pids/forked.pid'
> I0716 03:24:29.825053 2228 containerizer.cpp:537] Fetching URIs for container '50b2896d-0a67-4f83-9a73-f7fa7995081f' using command '/var/jenkins/workspace/mesos-fedora-19-clang/src/mesos-fetcher'
> I0716 03:24:29.825487 2231 slave.cpp:3836] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/runs/50b2896d-0a67-4f83-9a73-f7fa7995081f/tasks/adfda8a6-0064-41bc-afa8-74fa1f5b556c/task.info'
> I0716 03:24:29.826665 2231 slave.cpp:1222] Queuing task 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' for executor adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework '20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:29.836875 2231 slave.cpp:561] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/runs/50b2896d-0a67-4f83-9a73-f7fa7995081f'
> I0716 03:24:30.734251 2227 slave.cpp:2469] Monitoring executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework '20140716-032428-2272962752-50601-2209-0000' in container '50b2896d-0a67-4f83-9a73-f7fa7995081f'
> I0716 03:24:30.778158 2234 hierarchical_allocator_process.hpp:686] Performed allocation for 2 slaves in 59721ns
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0716 03:24:30.814615 5053 process.cpp:1671] libprocess is initialized on 192.168.122.135:55960 for 8 cpus
> I0716 03:24:30.820703 5053 exec.cpp:131] Version: 0.20.0
> I0716 03:24:30.822299 5102 exec.cpp:181] Executor started at: executor(1)@192.168.122.135:55960 with pid 5053
> I0716 03:24:30.832216 2229 slave.cpp:1733] Got registration for executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.832269 2229 slave.cpp:1818] Checkpointing executor pid 'executor(1)@192.168.122.135:55960' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/runs/50b2896d-0a67-4f83-9a73-f7fa7995081f/pids/libprocess.pid'
> I0716 03:24:30.833446 2229 slave.cpp:1852] Flushing queued task adfda8a6-0064-41bc-afa8-74fa1f5b556c for executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.833942 5101 exec.cpp:205] Executor registered on slave 20140716-032428-2272962752-50601-2209-1
> I0716 03:24:30.834766 5101 exec.cpp:217] Executor::registered took 112311ns
> Registered executor on fedora-19
> I0716 03:24:30.835422 5097 exec.cpp:292] Executor asked to run task 'adfda8a6-0064-41bc-afa8-74fa1f5b556c'
> I0716 03:24:30.835489 5097 exec.cpp:301] Executor::launchTask took 55940ns
> Starting task adfda8a6-0064-41bc-afa8-74fa1f5b556c
> sh -c 'sleep 1000'
> Forked command at 5106
> I0716 03:24:30.839438 5097 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.840128 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.840267 2227 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 from executor(1)@192.168.122.135:55960
> I0716 03:24:30.840358 2227 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.840373 2227 status_update_manager.cpp:499] Creating StatusUpdate stream for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.840643 5105 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.841433 2227 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.841495 2227 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 to master@192.168.122.135:50601
> I0716 03:24:30.841629 2227 master.cpp:3120] Status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 from slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:30.841667 2227 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.841678 2227 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 to executor(1)@192.168.122.135:55960
> I0716 03:24:30.841884 2227 sched.cpp:637] Scheduler::statusUpdate took 22305ns
> I0716 03:24:30.841944 2227 master.cpp:2639] Forwarding status update acknowledgement b4cf2946-426c-4c50-84cf-b2d4be2a74fa for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 to slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19)
> I0716 03:24:30.844437 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.844642 2227 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.844676 2227 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.844986 2227 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: b4cf2946-426c-4c50-84cf-b2d4be2a74fa) for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.845188 2209 slave.cpp:484] Slave terminating
> I0716 03:24:30.845654 2231 master.cpp:766] Slave 20140716-032428-2272962752-50601-2209-0 at slave(117)@192.168.122.135:50601 (fedora-19) disconnected
> I0716 03:24:30.845675 2231 master.cpp:1608] Disconnecting slave 20140716-032428-2272962752-50601-2209-0
> I0716 03:24:30.845777 2234 hierarchical_allocator_process.hpp:483] Slave 20140716-032428-2272962752-50601-2209-0 disconnected
> I0716 03:24:30.846804 2227 slave.cpp:484] Slave terminating
> I0716 03:24:30.847259 5098 exec.cpp:338] Executor received status update acknowledgement b4cf2946-426c-4c50-84cf-b2d4be2a74fa for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.847381 5105 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.848507 2227 master.cpp:766] Slave 20140716-032428-2272962752-50601-2209-1 at slave(118)@192.168.122.135:50601 (fedora-19) disconnected
> I0716 03:24:30.848557 2227 master.cpp:1608] Disconnecting slave 20140716-032428-2272962752-50601-2209-1
> I0716 03:24:30.848600 2227 hierarchical_allocator_process.hpp:483] Slave 20140716-032428-2272962752-50601-2209-1 disconnected
> I0716 03:24:30.849675 2209 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0716 03:24:30.854601 2209 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0716 03:24:30.855072 2231 slave.cpp:168] Slave started on 119)@192.168.122.135:50601
> I0716 03:24:30.855298 2231 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/credential'
> I0716 03:24:30.855414 2231 slave.cpp:266] Slave using credential for: test-principal
> I0716 03:24:30.855494 2231 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:30.855849 2231 slave.cpp:324] Slave hostname: fedora-19
> I0716 03:24:30.855867 2231 slave.cpp:325] Slave checkpoint: true
> I0716 03:24:30.856523 2231 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/meta'
> I0716 03:24:30.859191 2233 slave.cpp:3195] Recovering framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.859218 2233 slave.cpp:3571] Recovering executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.859549 2233 status_update_manager.cpp:193] Recovering status update manager
> I0716 03:24:30.859562 2233 status_update_manager.cpp:201] Recovering executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.859580 2233 status_update_manager.cpp:499] Creating StatusUpdate stream for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.859675 2233 status_update_manager.hpp:306] Replaying status update stream for task 89a4508d-6d24-42de-b0e3-56c95aad5ab7
> I0716 03:24:30.859786 2233 slave.cpp:561] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_j1YGF5/slaves/20140716-032428-2272962752-50601-2209-0/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/89a4508d-6d24-42de-b0e3-56c95aad5ab7/runs/5f163b4b-d329-4a6a-8c88-07d66a9e827c'
> I0716 03:24:30.859895 2233 containerizer.cpp:287] Recovering containerizer
> I0716 03:24:30.859915 2233 containerizer.cpp:329] Recovering container '5f163b4b-d329-4a6a-8c88-07d66a9e827c' for executor '89a4508d-6d24-42de-b0e3-56c95aad5ab7' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.861229 2231 slave.cpp:3068] Sending reconnect request to executor 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000 at executor(1)@192.168.122.135:44671
> I0716 03:24:30.862380 5049 exec.cpp:251] Received reconnect request from slave 20140716-032428-2272962752-50601-2209-0
> I0716 03:24:30.862982 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.863072 5051 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.867386 2231 slave.cpp:1912] Re-registering executor 89a4508d-6d24-42de-b0e3-56c95aad5ab7 of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.868245 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.869936 5046 exec.cpp:228] Executor re-registered on slave 20140716-032428-2272962752-50601-2209-0
> I0716 03:24:30.870709 5046 exec.cpp:240] Executor::reregistered took 51212ns
> Re-registered executor on fedora-19
> I0716 03:24:30.870784 5051 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.871526 2229 slave.cpp:168] Slave started on 120)@192.168.122.135:50601
> I0716 03:24:30.871552 2229 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/credential'
> I0716 03:24:30.871626 2229 slave.cpp:266] Slave using credential for: test-principal
> I0716 03:24:30.871769 2229 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 03:24:30.872154 2229 slave.cpp:324] Slave hostname: fedora-19
> I0716 03:24:30.872169 2229 slave.cpp:325] Slave checkpoint: true
> I0716 03:24:30.872474 2229 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/meta'
> I0716 03:24:30.873844 2228 slave.cpp:3195] Recovering framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.873873 2228 slave.cpp:3571] Recovering executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.874349 2228 slave.cpp:561] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_U3u0ah/slaves/20140716-032428-2272962752-50601-2209-1/frameworks/20140716-032428-2272962752-50601-2209-0000/executors/adfda8a6-0064-41bc-afa8-74fa1f5b556c/runs/50b2896d-0a67-4f83-9a73-f7fa7995081f'
> I0716 03:24:30.874377 2228 status_update_manager.cpp:193] Recovering status update manager
> I0716 03:24:30.874385 2228 status_update_manager.cpp:201] Recovering executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.874400 2228 status_update_manager.cpp:499] Creating StatusUpdate stream for task adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.874495 2228 status_update_manager.hpp:306] Replaying status update stream for task adfda8a6-0064-41bc-afa8-74fa1f5b556c
> I0716 03:24:30.874678 2228 containerizer.cpp:287] Recovering containerizer
> I0716 03:24:30.874701 2228 containerizer.cpp:329] Recovering container '50b2896d-0a67-4f83-9a73-f7fa7995081f' for executor 'adfda8a6-0064-41bc-afa8-74fa1f5b556c' of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.875670 2229 slave.cpp:3068] Sending reconnect request to executor adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000 at executor(1)@192.168.122.135:55960
> I0716 03:24:30.876314 5101 exec.cpp:251] Received reconnect request from slave 20140716-032428-2272962752-50601-2209-1
> I0716 03:24:30.876857 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.876919 5105 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.881351 2229 slave.cpp:1912] Re-registering executor adfda8a6-0064-41bc-afa8-74fa1f5b556c of framework 20140716-032428-2272962752-50601-2209-0000
> I0716 03:24:30.881731 2235 process.cpp:1098] Socket closed while receiving
> I0716 03:24:30.883246 5105 process.cpp:1037] Socket closed while receiving
> I0716 03:24:30.883313 5097 exec.cpp:228] Executor re-registered on slave 20140716-032428-2272962752-50601-2209-1
> Re-registered executor on fedora-19
> I0716 03:24:30.885090 5097 exec.cpp:240] Executor::reregistered took 97825ns
> 2014-07-16 03:24:32,054:2209(0x7f23e16d6700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 651ms
> 2014-07-16 03:24:32,054:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:35,391:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:38,727:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:42,064:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:45,400:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:48,736:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:52,072:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:55,408:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:24:58,744:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:02,081:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:05,418:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:08,825:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:12,165:2209(0x7f23e16d6700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 77ms
> 2014-07-16 03:25:12,165:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:15,501:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:18,837:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:22,173:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:25,510:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:28,846:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:32,182:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:35,690:2209(0x7f23e16d6700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:54016] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
> 2014-07-16 03:25:39,167:2209(0x7f23e16d6700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 316ms
> {noformat}
> {noformat: title=Successful run}
> [ RUN ] SlaveRecoveryTest/0.MultipleSlaves
> Using temporary directory '/tmp/SlaveRecoveryTest_0_MultipleSlaves_1POlPw'
> I0716 21:01:26.515823 8390 leveldb.cpp:176] Opened db in 154.152248ms
> I0716 21:01:26.534261 8390 leveldb.cpp:183] Compacted db in 18.393591ms
> I0716 21:01:26.534338 8390 leveldb.cpp:198] Created db iterator in 19969ns
> I0716 21:01:26.534373 8390 leveldb.cpp:204] Seeked to beginning of db in 2077ns
> I0716 21:01:26.534396 8390 leveldb.cpp:273] Iterated through 0 keys in the db in 422ns
> I0716 21:01:26.534447 8390 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0716 21:01:26.535167 8413 recover.cpp:425] Starting replica recovery
> I0716 21:01:26.536082 8423 recover.cpp:451] Replica is in EMPTY status
> I0716 21:01:26.537583 8406 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0716 21:01:26.538342 8409 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0716 21:01:26.538801 8413 recover.cpp:542] Updating replica status to STARTING
> I0716 21:01:26.539625 8409 master.cpp:288] Master 20140716-210126-1828659978-34280-8390 (<scrubbed_hostname>) started on <scrubbed_ip>:34280
> I0716 21:01:26.539722 8409 master.cpp:325] Master only allowing authenticated frameworks to register
> I0716 21:01:26.539741 8409 master.cpp:330] Master only allowing authenticated slaves to register
> I0716 21:01:26.539811 8409 credentials.hpp:36] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_1POlPw/credentials'
> I0716 21:01:26.540295 8409 master.cpp:359] Authorization enabled
> I0716 21:01:26.541703 8409 master.cpp:1128] The newly elected leader is master@<scrubbed_ip>:34280 with id 20140716-210126-1828659978-34280-8390
> I0716 21:01:26.541759 8409 master.cpp:1141] Elected as the leading master!
> I0716 21:01:26.541784 8409 master.cpp:959] Recovering from registrar
> I0716 21:01:26.541942 8416 registrar.cpp:313] Recovering registrar
> I0716 21:01:26.574594 8419 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 35.638255ms
> I0716 21:01:26.574641 8419 replica.cpp:320] Persisted replica status to STARTING
> I0716 21:01:26.574888 8419 recover.cpp:451] Replica is in STARTING status
> I0716 21:01:26.576969 8405 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0716 21:01:26.577390 8420 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0716 21:01:26.578193 8406 recover.cpp:542] Updating replica status to VOTING
> I0716 21:01:26.600301 8419 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 21.819505ms
> I0716 21:01:26.600356 8419 replica.cpp:320] Persisted replica status to VOTING
> I0716 21:01:26.600500 8419 recover.cpp:556] Successfully joined the Paxos group
> I0716 21:01:26.600704 8419 recover.cpp:440] Recover process terminated
> I0716 21:01:26.601346 8419 log.cpp:656] Attempting to start the writer
> I0716 21:01:26.602592 8417 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0716 21:01:26.608635 8417 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.969387ms
> I0716 21:01:26.608680 8417 replica.cpp:342] Persisted promised to 1
> I0716 21:01:26.609613 8419 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0716 21:01:26.611515 8422 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0716 21:01:26.617004 8422 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 5.352482ms
> I0716 21:01:26.617051 8422 replica.cpp:676] Persisted action at 0
> I0716 21:01:26.618556 8415 replica.cpp:508] Replica received write request for position 0
> I0716 21:01:26.618648 8415 leveldb.cpp:438] Reading position from leveldb took 43476ns
> I0716 21:01:26.625334 8415 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 6.640225ms
> I0716 21:01:26.625378 8415 replica.cpp:676] Persisted action at 0
> I0716 21:01:26.626132 8408 replica.cpp:655] Replica received learned notice for position 0
> I0716 21:01:26.633622 8408 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.443989ms
> I0716 21:01:26.633674 8408 replica.cpp:676] Persisted action at 0
> I0716 21:01:26.633710 8408 replica.cpp:661] Replica learned NOP action at position 0
> I0716 21:01:26.634166 8408 log.cpp:672] Writer started with ending position 0
> I0716 21:01:26.635740 8422 leveldb.cpp:438] Reading position from leveldb took 33194ns
> I0716 21:01:26.638562 8406 registrar.cpp:346] Successfully fetched the registry (0B)
> I0716 21:01:26.638639 8406 registrar.cpp:422] Attempting to update the 'registry'
> I0716 21:01:26.641350 8413 log.cpp:680] Attempting to append 154 bytes to the log
> I0716 21:01:26.641535 8426 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0716 21:01:26.642612 8427 replica.cpp:508] Replica received write request for position 1
> I0716 21:01:26.650290 8427 leveldb.cpp:343] Persisting action (173 bytes) to leveldb took 7.568997ms
> I0716 21:01:26.650341 8427 replica.cpp:676] Persisted action at 1
> I0716 21:01:26.651217 8423 replica.cpp:655] Replica received learned notice for position 1
> I0716 21:01:26.658648 8423 leveldb.cpp:343] Persisting action (175 bytes) to leveldb took 7.305209ms
> I0716 21:01:26.658694 8423 replica.cpp:676] Persisted action at 1
> I0716 21:01:26.658718 8423 replica.cpp:661] Replica learned APPEND action at position 1
> I0716 21:01:26.659754 8427 registrar.cpp:479] Successfully updated 'registry'
> I0716 21:01:26.659900 8427 registrar.cpp:372] Successfully recovered registrar
> I0716 21:01:26.660190 8415 master.cpp:986] Recovered 0 slaves from the Registry (116B) ; allowing 10mins for slaves to re-register
> I0716 21:01:26.660223 8427 log.cpp:699] Attempting to truncate the log to 1
> I0716 21:01:26.660358 8411 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0716 21:01:26.661243 8412 replica.cpp:508] Replica received write request for position 2
> I0716 21:01:26.666985 8412 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.652222ms
> I0716 21:01:26.667033 8412 replica.cpp:676] Persisted action at 2
> I0716 21:01:26.667829 8405 replica.cpp:655] Replica received learned notice for position 2
> I0716 21:01:26.675320 8405 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.426869ms
> I0716 21:01:26.675406 8405 leveldb.cpp:401] Deleting ~1 keys from leveldb took 35531ns
> I0716 21:01:26.675453 8405 replica.cpp:676] Persisted action at 2
> I0716 21:01:26.675478 8405 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0716 21:01:26.685824 8390 sched.cpp:139] Version: 0.20.0
> I0716 21:01:26.686420 8405 sched.cpp:235] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:26.686476 8405 sched.cpp:285] Authenticating with master master@<scrubbed_ip>:34280
> I0716 21:01:26.686704 8419 authenticatee.hpp:128] Creating new client SASL connection
> I0716 21:01:26.686869 8423 master.cpp:3512] Authenticating scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:26.687090 8415 authenticator.hpp:156] Creating new server SASL connection
> I0716 21:01:26.687221 8407 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 21:01:26.687254 8407 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 21:01:26.687369 8425 authenticator.hpp:262] Received SASL authentication start
> I0716 21:01:26.687477 8425 authenticator.hpp:384] Authentication requires more steps
> I0716 21:01:26.687561 8422 authenticatee.hpp:265] Received SASL authentication step
> I0716 21:01:26.687664 8412 authenticator.hpp:290] Received SASL authentication step
> I0716 21:01:26.687772 8412 authenticator.hpp:376] Authentication success
> I0716 21:01:26.687926 8421 master.cpp:3552] Successfully authenticated principal 'test-principal' at scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:26.687899 8412 authenticatee.hpp:305] Authentication success
> I0716 21:01:26.688346 8412 sched.cpp:359] Successfully authenticated with master master@<scrubbed_ip>:34280
> I0716 21:01:26.688562 8423 master.cpp:1247] Received registration request from scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:26.688638 8423 master.cpp:1207] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0716 21:01:26.689141 8414 master.cpp:1306] Registering framework 20140716-210126-1828659978-34280-8390-0000 at scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:26.689354 8416 sched.cpp:409] Framework registered with 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.689388 8390 containerizer.cpp:124] Using isolation: cgroups/cpu,cgroups/mem
> I0716 21:01:26.689476 8413 hierarchical_allocator_process.hpp:331] Added framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.714087 8390 linux_launcher.cpp:78] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> I0716 21:01:26.718397 8405 slave.cpp:168] Slave started on 441)@<scrubbed_ip>:34280
> I0716 21:01:26.718447 8405 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/credential'
> I0716 21:01:26.718586 8405 slave.cpp:266] Slave using credential for: test-principal
> I0716 21:01:26.718781 8405 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:26.719460 8405 slave.cpp:324] Slave hostname: <scrubbed_hostname>
> I0716 21:01:26.719498 8405 slave.cpp:325] Slave checkpoint: true
> I0716 21:01:26.720433 8421 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta'
> I0716 21:01:26.720734 8412 status_update_manager.cpp:193] Recovering status update manager
> I0716 21:01:26.721420 8420 containerizer.cpp:287] Recovering containerizer
> I0716 21:01:26.723884 8405 slave.cpp:3127] Finished recovery
> I0716 21:01:26.724310 8419 slave.cpp:600] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:26.724514 8426 status_update_manager.cpp:167] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:26.724529 8419 slave.cpp:676] Authenticating with master master@<scrubbed_ip>:34280
> I0716 21:01:26.724866 8419 slave.cpp:649] Detecting new master
> I0716 21:01:26.724944 8410 authenticatee.hpp:128] Creating new client SASL connection
> I0716 21:01:26.725170 8410 master.cpp:3512] Authenticating slave(441)@<scrubbed_ip>:34280
> I0716 21:01:26.725406 8424 authenticator.hpp:156] Creating new server SASL connection
> I0716 21:01:26.725523 8407 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 21:01:26.725549 8407 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 21:01:26.725929 8422 authenticator.hpp:262] Received SASL authentication start
> I0716 21:01:26.726023 8422 authenticator.hpp:384] Authentication requires more steps
> I0716 21:01:26.726109 8422 authenticatee.hpp:265] Received SASL authentication step
> I0716 21:01:26.726196 8422 authenticator.hpp:290] Received SASL authentication step
> I0716 21:01:26.726263 8422 authenticator.hpp:376] Authentication success
> I0716 21:01:26.726362 8423 authenticatee.hpp:305] Authentication success
> I0716 21:01:26.726421 8411 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(441)@<scrubbed_ip>:34280
> I0716 21:01:26.726605 8415 slave.cpp:733] Successfully authenticated with master master@<scrubbed_ip>:34280
> I0716 21:01:26.726881 8420 master.cpp:2789] Registering slave at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>) with id 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:26.727212 8417 registrar.cpp:422] Attempting to update the 'registry'
> I0716 21:01:26.729677 8418 log.cpp:680] Attempting to append 380 bytes to the log
> I0716 21:01:26.729825 8408 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0716 21:01:26.730765 8419 replica.cpp:508] Replica received write request for position 3
> I0716 21:01:26.745239 8408 master.cpp:2777] Ignoring register slave message from slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>) as admission is already in progress
> I0716 21:01:26.750272 8419 leveldb.cpp:343] Persisting action (399 bytes) to leveldb took 19.454893ms
> I0716 21:01:26.750326 8419 replica.cpp:676] Persisted action at 3
> I0716 21:01:26.750991 8417 replica.cpp:655] Replica received learned notice for position 3
> I0716 21:01:26.758602 8417 leveldb.cpp:343] Persisting action (401 bytes) to leveldb took 7.566502ms
> I0716 21:01:26.758654 8417 replica.cpp:676] Persisted action at 3
> I0716 21:01:26.758690 8417 replica.cpp:661] Replica learned APPEND action at position 3
> I0716 21:01:26.759807 8420 registrar.cpp:479] Successfully updated 'registry'
> I0716 21:01:26.760094 8420 master.cpp:2829] Registered slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:26.760128 8420 master.cpp:3980] Adding slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:26.760177 8417 log.cpp:699] Attempting to truncate the log to 3
> I0716 21:01:26.760335 8407 slave.cpp:767] Registered with master master@<scrubbed_ip>:34280; given slave ID 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:26.760444 8425 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0716 21:01:26.760504 8407 slave.cpp:780] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/slave.info'
> I0716 21:01:26.760612 8426 hierarchical_allocator_process.hpp:444] Added slave 20140716-210126-1828659978-34280-8390-0 (<scrubbed_hostname>) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0716 21:01:26.761297 8412 replica.cpp:508] Replica received write request for position 4
> I0716 21:01:26.761546 8427 master.cpp:3459] Sending 1 offers to framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.764883 8410 master.cpp:2133] Processing reply for offers: [ 20140716-210126-1828659978-34280-8390-0 ] on slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>) for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.765048 8410 master.cpp:2219] Authorizing framework principal 'test-principal' to launch task 038aad52-c394-44ea-9d48-6ef34cdac69a as user 'root'
> I0716 21:01:26.766031 8422 master.hpp:774] Adding task 038aad52-c394-44ea-9d48-6ef34cdac69a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-0 (<scrubbed_hostname>)
> I0716 21:01:26.766185 8422 master.cpp:2285] Launching task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:26.766424 8419 slave.cpp:1002] Got assigned task 038aad52-c394-44ea-9d48-6ef34cdac69a for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.766572 8419 slave.cpp:3399] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.info'
> I0716 21:01:26.766778 8419 slave.cpp:3406] Checkpointing framework pid 'scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.pid'
> I0716 21:01:26.766948 8412 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.600638ms
> I0716 21:01:26.766988 8412 replica.cpp:676] Persisted action at 4
> I0716 21:01:26.767587 8422 replica.cpp:655] Replica received learned notice for position 4
> I0716 21:01:26.767593 8419 slave.cpp:1112] Launching task 038aad52-c394-44ea-9d48-6ef34cdac69a for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.770113 8419 slave.cpp:3721] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/executor.info'
> I0716 21:01:26.770870 8413 containerizer.cpp:427] Starting container '491a9db1-b088-4093-9455-eb1a5ff834b7' for executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework '20140716-210126-1828659978-34280-8390-0000'
> I0716 21:01:26.770898 8419 slave.cpp:3836] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/runs/491a9db1-b088-4093-9455-eb1a5ff834b7/tasks/038aad52-c394-44ea-9d48-6ef34cdac69a/task.info'
> I0716 21:01:26.771111 8419 slave.cpp:1222] Queuing task '038aad52-c394-44ea-9d48-6ef34cdac69a' for executor 038aad52-c394-44ea-9d48-6ef34cdac69a of framework '20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:26.773222 8414 mem.cpp:425] Started listening for OOM events for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:26.773762 8414 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:26.774579 8408 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:26.774723 8414 mem.cpp:305] Updated 'memory.limit_in_bytes' to 1056MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:26.775416 8422 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.665336ms
> I0716 21:01:26.775552 8422 leveldb.cpp:401] Deleting ~2 keys from leveldb took 39519ns
> I0716 21:01:26.775589 8422 replica.cpp:676] Persisted action at 4
> I0716 21:01:26.775627 8422 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0716 21:01:26.777163 8420 linux_launcher.cpp:191] Cloning child process with flags = 0
> I0716 21:01:26.785720 8420 containerizer.cpp:705] Checkpointing executor's forked pid 26555 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/runs/491a9db1-b088-4093-9455-eb1a5ff834b7/pids/forked.pid'
> I0716 21:01:26.818495 8411 containerizer.cpp:537] Fetching URIs for container '491a9db1-b088-4093-9455-eb1a5ff834b7' using command '/home/bmahler/git/mesos/build/src/mesos-fetcher'
> I0716 21:01:27.250658 8408 slave.cpp:2469] Monitoring executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework '20140716-210126-1828659978-34280-8390-0000' in container '491a9db1-b088-4093-9455-eb1a5ff834b7'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0716 21:01:27.295753 26555 exec.cpp:131] Version: 0.20.0
> I0716 21:01:27.301416 8406 slave.cpp:1733] Got registration for executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.301519 8406 slave.cpp:1818] Checkpointing executor pid 'executor(1)@<scrubbed_ip>:45703' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/runs/491a9db1-b088-4093-9455-eb1a5ff834b7/pids/libprocess.pid'
> I0716 21:01:27.303041 8406 slave.cpp:1852] Flushing queued task 038aad52-c394-44ea-9d48-6ef34cdac69a for executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.303853 26610 exec.cpp:205] Executor registered on slave 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:27.304323 8412 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:27.304568 8414 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> Registered executor on <scrubbed_hostname>
> Starting task 038aad52-c394-44ea-9d48-6ef34cdac69a
> sh -c 'sleep 1000'
> Forked command at 26629
> I0716 21:01:27.311446 8408 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 from executor(1)@<scrubbed_ip>:45703
> I0716 21:01:27.311791 8420 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.312366 8420 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.433979 8420 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to master@<scrubbed_ip>:34280
> I0716 21:01:27.434289 8420 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to executor(1)@<scrubbed_ip>:45703
> I0716 21:01:27.434423 8414 master.cpp:3120] Status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 from slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:27.434828 8408 master.cpp:2639] Forwarding status update acknowledgement 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:27.435475 8408 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.435556 8408 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 0e34c58b-9b2b-49a5-b7f8-7cc32d63783d) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.520890 8390 containerizer.cpp:124] Using isolation: cgroups/cpu,cgroups/mem
> I0716 21:01:27.539791 8390 linux_launcher.cpp:78] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> I0716 21:01:27.545184 8424 slave.cpp:168] Slave started on 442)@<scrubbed_ip>:34280
> I0716 21:01:27.545214 8424 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/credential'
> I0716 21:01:27.545342 8424 slave.cpp:266] Slave using credential for: test-principal
> I0716 21:01:27.545518 8424 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:27.545999 8424 slave.cpp:324] Slave hostname: <scrubbed_hostname>
> I0716 21:01:27.546020 8424 slave.cpp:325] Slave checkpoint: true
> I0716 21:01:27.547302 8412 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta'
> I0716 21:01:27.547646 8418 status_update_manager.cpp:193] Recovering status update manager
> I0716 21:01:27.547921 8417 containerizer.cpp:287] Recovering containerizer
> I0716 21:01:27.551633 8424 slave.cpp:3127] Finished recovery
> I0716 21:01:27.552165 8423 slave.cpp:600] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:27.552284 8416 status_update_manager.cpp:167] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:27.552299 8423 slave.cpp:676] Authenticating with master master@<scrubbed_ip>:34280
> I0716 21:01:27.552778 8423 slave.cpp:649] Detecting new master
> I0716 21:01:27.552831 8406 authenticatee.hpp:128] Creating new client SASL connection
> I0716 21:01:27.553153 8416 master.cpp:3512] Authenticating slave(442)@<scrubbed_ip>:34280
> I0716 21:01:27.553403 8420 authenticator.hpp:156] Creating new server SASL connection
> I0716 21:01:27.553534 8415 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 21:01:27.553562 8415 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 21:01:27.553629 8415 authenticator.hpp:262] Received SASL authentication start
> I0716 21:01:27.553678 8415 authenticator.hpp:384] Authentication requires more steps
> I0716 21:01:27.553783 8406 authenticatee.hpp:265] Received SASL authentication step
> I0716 21:01:27.553966 8417 authenticator.hpp:290] Received SASL authentication step
> I0716 21:01:27.554081 8417 authenticator.hpp:376] Authentication success
> I0716 21:01:27.554203 8414 authenticatee.hpp:305] Authentication success
> I0716 21:01:27.554239 8419 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(442)@<scrubbed_ip>:34280
> I0716 21:01:27.554402 8417 slave.cpp:733] Successfully authenticated with master master@<scrubbed_ip>:34280
> I0716 21:01:27.554803 8413 master.cpp:2789] Registering slave at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) with id 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:27.555258 8424 registrar.cpp:422] Attempting to update the 'registry'
> I0716 21:01:27.557793 8414 log.cpp:680] Attempting to append 602 bytes to the log
> I0716 21:01:27.558019 8423 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0716 21:01:27.559032 8428 replica.cpp:508] Replica received write request for position 5
> I0716 21:01:27.570147 8406 master.cpp:2777] Ignoring register slave message from slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) as admission is already in progress
> I0716 21:01:27.571537 8416 master.cpp:2777] Ignoring register slave message from slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) as admission is already in progress
> I0716 21:01:27.574872 8428 leveldb.cpp:343] Persisting action (621 bytes) to leveldb took 15.786667ms
> I0716 21:01:27.574970 8428 replica.cpp:676] Persisted action at 5
> I0716 21:01:27.575626 8421 replica.cpp:655] Replica received learned notice for position 5
> I0716 21:01:27.626199 8421 leveldb.cpp:343] Persisting action (623 bytes) to leveldb took 50.518547ms
> I0716 21:01:27.626291 8421 replica.cpp:676] Persisted action at 5
> I0716 21:01:27.626327 8421 replica.cpp:661] Replica learned APPEND action at position 5
> I0716 21:01:27.627686 8408 registrar.cpp:479] Successfully updated 'registry'
> I0716 21:01:27.628128 8413 log.cpp:699] Attempting to truncate the log to 5
> I0716 21:01:27.628345 8422 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0716 21:01:27.628813 8423 master.cpp:2829] Registered slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:27.628937 8423 master.cpp:3980] Adding slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:27.629804 8414 replica.cpp:508] Replica received write request for position 6
> I0716 21:01:27.629842 8418 slave.cpp:767] Registered with master master@<scrubbed_ip>:34280; given slave ID 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:27.630102 8418 slave.cpp:780] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/slave.info'
> I0716 21:01:27.630108 8423 hierarchical_allocator_process.hpp:444] Added slave 20140716-210126-1828659978-34280-8390-1 (<scrubbed_hostname>) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0716 21:01:27.631070 8427 master.cpp:3459] Sending 1 offers to framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.634517 8411 master.cpp:2133] Processing reply for offers: [ 20140716-210126-1828659978-34280-8390-1 ] on slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.634627 8411 master.cpp:2219] Authorizing framework principal 'test-principal' to launch task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 as user 'root'
> I0716 21:01:27.635818 8428 master.hpp:774] Adding task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-1 (<scrubbed_hostname>)
> I0716 21:01:27.635951 8428 master.cpp:2285] Launching task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:27.636333 8409 slave.cpp:1002] Got assigned task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.636576 8409 slave.cpp:3399] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.info'
> I0716 21:01:27.636752 8409 slave.cpp:3406] Checkpointing framework pid 'scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.pid'
> I0716 21:01:27.637253 8409 slave.cpp:1112] Launching task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.639462 8409 slave.cpp:3721] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/executor.info'
> I0716 21:01:27.640279 8409 slave.cpp:3836] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/runs/c678ebbb-e810-409c-9503-ea2e24cdb10b/tasks/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/task.info'
> I0716 21:01:27.640291 8413 containerizer.cpp:427] Starting container 'c678ebbb-e810-409c-9503-ea2e24cdb10b' for executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework '20140716-210126-1828659978-34280-8390-0000'
> I0716 21:01:27.640569 8409 slave.cpp:1222] Queuing task '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' for executor 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework '20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:27.643133 8422 mem.cpp:425] Started listening for OOM events for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:27.643759 8422 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:27.644191 8409 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:27.644845 8422 mem.cpp:305] Updated 'memory.limit_in_bytes' to 1056MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:27.647047 8408 linux_launcher.cpp:191] Cloning child process with flags = 0
> I0716 21:01:27.648901 8408 containerizer.cpp:705] Checkpointing executor's forked pid 26634 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/runs/c678ebbb-e810-409c-9503-ea2e24cdb10b/pids/forked.pid'
> I0716 21:01:27.650596 8414 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 20.134647ms
> I0716 21:01:27.650709 8414 replica.cpp:676] Persisted action at 6
> I0716 21:01:27.652431 8409 replica.cpp:655] Replica received learned notice for position 6
> I0716 21:01:27.658133 8409 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.663082ms
> I0716 21:01:27.658226 8409 leveldb.cpp:401] Deleting ~2 keys from leveldb took 42383ns
> I0716 21:01:27.658274 8409 replica.cpp:676] Persisted action at 6
> I0716 21:01:27.658324 8409 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0716 21:01:27.925734 8412 containerizer.cpp:537] Fetching URIs for container 'c678ebbb-e810-409c-9503-ea2e24cdb10b' using command '/home/bmahler/git/mesos/build/src/mesos-fetcher'
> I0716 21:01:28.258239 8418 slave.cpp:2469] Monitoring executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework '20140716-210126-1828659978-34280-8390-0000' in container 'c678ebbb-e810-409c-9503-ea2e24cdb10b'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0716 21:01:28.305376 26634 exec.cpp:131] Version: 0.20.0
> I0716 21:01:28.310770 8409 slave.cpp:1733] Got registration for executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.311327 8409 slave.cpp:1818] Checkpointing executor pid 'executor(1)@<scrubbed_ip>:44177' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/runs/c678ebbb-e810-409c-9503-ea2e24cdb10b/pids/libprocess.pid'
> I0716 21:01:28.312628 8409 slave.cpp:1852] Flushing queued task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 for executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.313621 26686 exec.cpp:205] Executor registered on slave 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:28.314306 8406 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:28.314599 8427 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> Registered executor on <scrubbed_hostname>
> Starting task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829
> sh -c 'sleep 1000'
> Forked command at 26707
> I0716 21:01:28.320516 8407 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 from executor(1)@<scrubbed_ip>:44177
> I0716 21:01:28.320807 8415 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.321445 8415 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.435570 8415 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to master@<scrubbed_ip>:34280
> I0716 21:01:28.436069 8423 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to executor(1)@<scrubbed_ip>:44177
> I0716 21:01:28.436189 8420 master.cpp:3120] Status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 from slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:28.436616 8422 master.cpp:2639] Forwarding status update acknowledgement 28a0fd5f-1010-4bfb-927f-4ae24c71af0d for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:28.437001 8426 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.437065 8426 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 28a0fd5f-1010-4bfb-927f-4ae24c71af0d) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.520320 8390 slave.cpp:484] Slave terminating
> I0716 21:01:28.520654 8420 master.cpp:766] Slave 20140716-210126-1828659978-34280-8390-0 at slave(441)@<scrubbed_ip>:34280 (<scrubbed_hostname>) disconnected
> I0716 21:01:28.520895 8420 master.cpp:1608] Disconnecting slave 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:28.521109 8413 hierarchical_allocator_process.hpp:483] Slave 20140716-210126-1828659978-34280-8390-0 disconnected
> I0716 21:01:28.525732 8409 slave.cpp:484] Slave terminating
> I0716 21:01:28.525895 8423 master.cpp:766] Slave 20140716-210126-1828659978-34280-8390-1 at slave(442)@<scrubbed_ip>:34280 (<scrubbed_hostname>) disconnected
> I0716 21:01:28.525940 8423 master.cpp:1608] Disconnecting slave 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:28.526106 8420 hierarchical_allocator_process.hpp:483] Slave 20140716-210126-1828659978-34280-8390-1 disconnected
> I0716 21:01:28.528478 8390 containerizer.cpp:124] Using isolation: cgroups/cpu,cgroups/mem
> I0716 21:01:28.544284 8390 linux_launcher.cpp:78] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> I0716 21:01:28.549222 8422 slave.cpp:168] Slave started on 443)@<scrubbed_ip>:34280
> I0716 21:01:28.549273 8422 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/credential'
> I0716 21:01:28.549464 8422 slave.cpp:266] Slave using credential for: test-principal
> I0716 21:01:28.549660 8390 containerizer.cpp:124] Using isolation: cgroups/cpu,cgroups/mem
> I0716 21:01:28.549674 8422 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:28.550019 8422 slave.cpp:324] Slave hostname: <scrubbed_hostname>
> I0716 21:01:28.550051 8422 slave.cpp:325] Slave checkpoint: true
> I0716 21:01:28.550997 8406 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta'
> I0716 21:01:28.553601 8418 slave.cpp:3195] Recovering framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.553663 8418 slave.cpp:3571] Recovering executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.554599 8410 status_update_manager.cpp:193] Recovering status update manager
> I0716 21:01:28.554646 8410 status_update_manager.cpp:201] Recovering executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.555846 8416 containerizer.cpp:287] Recovering containerizer
> I0716 21:01:28.555971 8416 containerizer.cpp:329] Recovering container '491a9db1-b088-4093-9455-eb1a5ff834b7' for executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.559325 8424 mem.cpp:425] Started listening for OOM events for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:28.561152 8408 slave.cpp:3068] Sending reconnect request to executor 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 at executor(1)@<scrubbed_ip>:45703
> I0716 21:01:28.561859 26615 exec.cpp:251] Received reconnect request from slave 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:28.562707 8413 slave.cpp:1912] Re-registering executor 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.563328 26620 exec.cpp:228] Executor re-registered on slave 20140716-210126-1828659978-34280-8390-0
> I0716 21:01:28.564086 8405 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:28.564098 8413 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:28.565183 8405 mem.cpp:305] Updated 'memory.limit_in_bytes' to 1056MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> Re-registered executor on <scrubbed_hostname>
> I0716 21:01:28.570299 8390 linux_launcher.cpp:78] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> I0716 21:01:28.574300 8411 slave.cpp:168] Slave started on 444)@<scrubbed_ip>:34280
> I0716 21:01:28.574334 8411 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/credential'
> I0716 21:01:28.574465 8411 slave.cpp:266] Slave using credential for: test-principal
> I0716 21:01:28.574625 8411 slave.cpp:279] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 21:01:28.574935 8411 slave.cpp:324] Slave hostname: <scrubbed_hostname>
> I0716 21:01:28.574961 8411 slave.cpp:325] Slave checkpoint: true
> I0716 21:01:28.575737 8415 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta'
> I0716 21:01:28.577771 8420 slave.cpp:3195] Recovering framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.577915 8420 slave.cpp:3571] Recovering executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.578763 8407 status_update_manager.cpp:193] Recovering status update manager
> I0716 21:01:28.578796 8407 status_update_manager.cpp:201] Recovering executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.579779 8415 containerizer.cpp:287] Recovering containerizer
> I0716 21:01:28.579875 8415 containerizer.cpp:329] Recovering container 'c678ebbb-e810-409c-9503-ea2e24cdb10b' for executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.583179 8411 mem.cpp:425] Started listening for OOM events for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:28.585021 8428 slave.cpp:3068] Sending reconnect request to executor 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 at executor(1)@<scrubbed_ip>:44177
> I0716 21:01:28.585543 26689 exec.cpp:251] Received reconnect request from slave 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:28.586287 8410 slave.cpp:1912] Re-registering executor 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.586928 26684 exec.cpp:228] Executor re-registered on slave 20140716-210126-1828659978-34280-8390-1
> I0716 21:01:28.587530 8405 cpushare.cpp:344] Updated 'cpu.shares' to 2150 (cpus 2.1) for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:28.587627 8425 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 1056MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:28.588596 8425 mem.cpp:305] Updated 'memory.limit_in_bytes' to 1056MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> Re-registered executor on <scrubbed_hostname>
> I0716 21:01:28.615757 8425 slave.cpp:2036] Cleaning up un-reregistered executors
> I0716 21:01:28.615847 8425 slave.cpp:3127] Finished recovery
> I0716 21:01:28.615792 8422 slave.cpp:2036] Cleaning up un-reregistered executors
> I0716 21:01:28.616106 8422 slave.cpp:3127] Finished recovery
> I0716 21:01:28.616479 8427 slave.cpp:600] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:28.616576 8416 status_update_manager.cpp:167] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:28.616554 8427 slave.cpp:676] Authenticating with master master@<scrubbed_ip>:34280
> I0716 21:01:28.616972 8416 slave.cpp:600] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:28.617283 8427 slave.cpp:649] Detecting new master
> I0716 21:01:28.617321 8416 slave.cpp:676] Authenticating with master master@<scrubbed_ip>:34280
> I0716 21:01:28.617341 8428 status_update_manager.cpp:167] New master detected at master@<scrubbed_ip>:34280
> I0716 21:01:28.617888 8416 slave.cpp:649] Detecting new master
> I0716 21:01:28.618100 8428 authenticatee.hpp:128] Creating new client SASL connection
> I0716 21:01:28.618100 8417 authenticatee.hpp:128] Creating new client SASL connection
> I0716 21:01:28.618369 8408 master.cpp:3512] Authenticating slave(444)@<scrubbed_ip>:34280
> I0716 21:01:28.618818 8411 authenticator.hpp:156] Creating new server SASL connection
> I0716 21:01:28.618935 8408 master.cpp:3512] Authenticating slave(443)@<scrubbed_ip>:34280
> I0716 21:01:28.619052 8427 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 21:01:28.619083 8427 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 21:01:28.619256 8422 authenticator.hpp:262] Received SASL authentication start
> I0716 21:01:28.619282 8420 authenticator.hpp:156] Creating new server SASL connection
> I0716 21:01:28.619350 8422 authenticator.hpp:384] Authentication requires more steps
> I0716 21:01:28.619439 8426 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0716 21:01:28.619489 8426 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 21:01:28.619725 8408 authenticator.hpp:262] Received SASL authentication start
> I0716 21:01:28.619789 8408 authenticator.hpp:384] Authentication requires more steps
> I0716 21:01:28.619879 8408 authenticatee.hpp:265] Received SASL authentication step
> I0716 21:01:28.619916 8405 authenticatee.hpp:265] Received SASL authentication step
> I0716 21:01:28.620002 8408 authenticator.hpp:290] Received SASL authentication step
> I0716 21:01:28.620030 8422 authenticator.hpp:290] Received SASL authentication step
> I0716 21:01:28.620107 8408 authenticator.hpp:376] Authentication success
> I0716 21:01:28.620157 8422 authenticator.hpp:376] Authentication success
> I0716 21:01:28.620200 8420 authenticatee.hpp:305] Authentication success
> I0716 21:01:28.620288 8411 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(443)@<scrubbed_ip>:34280
> I0716 21:01:28.620332 8409 authenticatee.hpp:305] Authentication success
> I0716 21:01:28.620544 8411 master.cpp:3552] Successfully authenticated principal 'test-principal' at slave(444)@<scrubbed_ip>:34280
> I0716 21:01:28.620791 8416 slave.cpp:733] Successfully authenticated with master master@<scrubbed_ip>:34280
> I0716 21:01:28.620903 8408 slave.cpp:733] Successfully authenticated with master master@<scrubbed_ip>:34280
> W0716 21:01:28.621253 8406 master.cpp:2904] Slave at slave(444)@<scrubbed_ip>:34280 (<scrubbed_hostname>) is being allowed to re-register with an already in use id (20140716-210126-1828659978-34280-8390-1)
> I0716 21:01:28.621515 8413 slave.cpp:817] Re-registered with master master@<scrubbed_ip>:34280
> I0716 21:01:28.621572 8427 hierarchical_allocator_process.hpp:497] Slave 20140716-210126-1828659978-34280-8390-1 reconnected
> I0716 21:01:28.621673 8411 slave.cpp:1583] Updating framework 20140716-210126-1828659978-34280-8390-0000 pid to scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:28.621748 8411 slave.cpp:1591] Checkpointing framework pid 'scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.pid'
> W0716 21:01:28.621891 8406 master.cpp:2904] Slave at slave(443)@<scrubbed_ip>:34280 (<scrubbed_hostname>) is being allowed to re-register with an already in use id (20140716-210126-1828659978-34280-8390-0)
> I0716 21:01:28.622134 8422 slave.cpp:817] Re-registered with master master@<scrubbed_ip>:34280
> I0716 21:01:28.622242 8405 hierarchical_allocator_process.hpp:497] Slave 20140716-210126-1828659978-34280-8390-0 reconnected
> I0716 21:01:28.622303 8422 slave.cpp:1583] Updating framework 20140716-210126-1828659978-34280-8390-0000 pid to scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280
> I0716 21:01:28.622359 8422 slave.cpp:1591] Checkpointing framework pid 'scheduler-1ad6eab4-da20-4dd4-920c-3980030a9bda@<scrubbed_ip>:34280' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/framework.pid'
> I0716 21:01:28.625715 8410 master.cpp:2469] Asked to kill task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.625794 8410 master.cpp:2570] Telling slave 20140716-210126-1828659978-34280-8390-0 at slave(443)@<scrubbed_ip>:34280 (<scrubbed_hostname>) to kill task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.626087 8419 slave.cpp:1278] Asked to kill task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.626127 8410 master.cpp:2469] Asked to kill task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.626210 8410 master.cpp:2570] Telling slave 20140716-210126-1828659978-34280-8390-1 at slave(444)@<scrubbed_ip>:34280 (<scrubbed_hostname>) to kill task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:28.626322 8419 slave.cpp:1278] Asked to kill task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> Shutting down
> Sending SIGTERM to process tree at pid 26629
> Shutting down
> Sending SIGTERM to process tree at pid 26707
> Killing the following process trees:
> [
> --- 26707 sleep 1000
> ]
> Killing the following process trees:
> [
> --- 26629 sleep 1000
> ]
> Command terminated with signal Terminated (pid: 26629)
> I0716 21:01:29.313376 8421 slave.cpp:2087] Handling status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 from executor(1)@<scrubbed_ip>:45703
> I0716 21:01:29.315099 8409 cpushare.cpp:344] Updated 'cpu.shares' to 102 (cpus 0.1) for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:29.315214 8405 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 32MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:29.316297 8405 mem.cpp:305] Updated 'memory.limit_in_bytes' to 32MB for container 491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:29.317495 8421 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.317570 8421 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> Command terminated with signal Terminated (pid: 26707)
> I0716 21:01:29.320796 8428 slave.cpp:2087] Handling status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 from executor(1)@<scrubbed_ip>:44177
> I0716 21:01:29.322417 8426 mem.cpp:275] Updated 'memory.soft_limit_in_bytes' to 32MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:29.322437 8410 cpushare.cpp:344] Updated 'cpu.shares' to 102 (cpus 0.1) for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:29.323457 8426 mem.cpp:305] Updated 'memory.limit_in_bytes' to 32MB for container c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:29.324139 8409 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.324224 8409 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.485882 8421 status_update_manager.cpp:373] Forwarding status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to master@<scrubbed_ip>:34280
> I0716 21:01:29.486171 8416 slave.cpp:2251] Sending acknowledgement for status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to executor(1)@<scrubbed_ip>:45703
> I0716 21:01:29.486258 8422 master.cpp:3120] Status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 from slave 20140716-210126-1828659978-34280-8390-0 at slave(443)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:29.486754 8422 master.hpp:792] Removing task 038aad52-c394-44ea-9d48-6ef34cdac69a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-0 (<scrubbed_hostname>)
> I0716 21:01:29.487185 8422 master.cpp:2639] Forwarding status update acknowledgement 2c817974-fb57-40a5-b634-afc8eade82eb for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000 to slave 20140716-210126-1828659978-34280-8390-0 at slave(443)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:29.487750 8426 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 20140716-210126-1828659978-34280-8390-0 from framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.488441 8426 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.488538 8426 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_KILLED (UUID: 2c817974-fb57-40a5-b634-afc8eade82eb) for task 038aad52-c394-44ea-9d48-6ef34cdac69a of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.516885 8409 status_update_manager.cpp:373] Forwarding status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to master@<scrubbed_ip>:34280
> I0716 21:01:29.517236 8417 slave.cpp:2251] Sending acknowledgement for status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to executor(1)@<scrubbed_ip>:44177
> I0716 21:01:29.517331 8422 master.cpp:3120] Status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 from slave 20140716-210126-1828659978-34280-8390-1 at slave(444)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:29.517622 8422 master.hpp:792] Removing task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140716-210126-1828659978-34280-8390-1 (<scrubbed_hostname>)
> I0716 21:01:29.517983 8422 master.cpp:2639] Forwarding status update acknowledgement 6907ec8a-dfc8-449f-ac15-2c5e76acf737 for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000 to slave 20140716-210126-1828659978-34280-8390-1 at slave(444)@<scrubbed_ip>:34280 (<scrubbed_hostname>)
> I0716 21:01:29.518349 8405 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 20140716-210126-1828659978-34280-8390-1 from framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.518645 8419 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.518713 8419 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_KILLED (UUID: 6907ec8a-dfc8-449f-ac15-2c5e76acf737) for task 1e00dd3c-5c2d-4423-b6b6-74a0b90b7829 of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:29.577286 8427 master.cpp:3459] Sending 2 offers to framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.576637 8406 containerizer.cpp:1019] Executor for container '491a9db1-b088-4093-9455-eb1a5ff834b7' has exited
> I0716 21:01:30.576688 8406 containerizer.cpp:903] Destroying container '491a9db1-b088-4093-9455-eb1a5ff834b7'
> I0716 21:01:30.577165 8411 containerizer.cpp:1019] Executor for container 'c678ebbb-e810-409c-9503-ea2e24cdb10b' has exited
> I0716 21:01:30.577226 8411 containerizer.cpp:903] Destroying container 'c678ebbb-e810-409c-9503-ea2e24cdb10b'
> I0716 21:01:30.578706 8421 cgroups.cpp:2021] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5/491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:30.579246 8412 cgroups.cpp:2021] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d/c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:30.580721 8417 cgroups.cpp:1375] Successfullly froze cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5/491a9db1-b088-4093-9455-eb1a5ff834b7 after 1.958912ms
> I0716 21:01:30.581804 8425 cgroups.cpp:1375] Successfullly froze cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d/c678ebbb-e810-409c-9503-ea2e24cdb10b after 2.505216ms
> I0716 21:01:30.583652 8426 cgroups.cpp:2038] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5/491a9db1-b088-4093-9455-eb1a5ff834b7
> I0716 21:01:30.584430 8427 cgroups.cpp:2038] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d/c678ebbb-e810-409c-9503-ea2e24cdb10b
> I0716 21:01:30.585579 8420 cgroups.cpp:1404] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5/491a9db1-b088-4093-9455-eb1a5ff834b7 after 1.873152ms
> I0716 21:01:30.586170 8415 cgroups.cpp:1404] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d/c678ebbb-e810-409c-9503-ea2e24cdb10b after 1.666048ms
> I0716 21:01:30.598176 8426 slave.cpp:2527] Executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000 exited with status 0
> I0716 21:01:30.598316 8426 slave.cpp:2661] Cleaning up executor '038aad52-c394-44ea-9d48-6ef34cdac69a' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.598701 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/runs/491a9db1-b088-4093-9455-eb1a5ff834b7' for gc 6.99999307244148days in the future
> I0716 21:01:30.598829 8426 slave.cpp:2736] Cleaning up framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.598870 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a' for gc 6.9999930708563days in the future
> I0716 21:01:30.598924 8410 status_update_manager.cpp:282] Closing status update streams for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.599004 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a/runs/491a9db1-b088-4093-9455-eb1a5ff834b7' for gc 6.99999307021037days in the future
> I0716 21:01:30.599122 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/038aad52-c394-44ea-9d48-6ef34cdac69a' for gc 6.99999306962963days in the future
> I0716 21:01:30.599233 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000' for gc 6.99999306827556days in the future
> I0716 21:01:30.599340 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_7ho9IQ/meta/slaves/20140716-210126-1828659978-34280-8390-0/frameworks/20140716-210126-1828659978-34280-8390-0000' for gc 6.99999306754667days in the future
> I0716 21:01:30.734809 8417 slave.cpp:2527] Executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000 exited with status 0
> I0716 21:01:30.735477 8417 slave.cpp:2661] Cleaning up executor '1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' of framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.736491 8424 master.cpp:625] Master terminating
> I0716 21:01:30.736532 8420 sched.cpp:747] Stopping framework '20140716-210126-1828659978-34280-8390-0000'
> I0716 21:01:30.736606 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/runs/c678ebbb-e810-409c-9503-ea2e24cdb10b' for gc 6.99999148577481days in the future
> I0716 21:01:30.736814 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' for gc 6.99999147421333days in the future
> I0716 21:01:30.736840 8417 slave.cpp:2736] Cleaning up framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.736992 8418 status_update_manager.cpp:282] Closing status update streams for framework 20140716-210126-1828659978-34280-8390-0000
> I0716 21:01:30.737006 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829/runs/c678ebbb-e810-409c-9503-ea2e24cdb10b' for gc 6.99999147293037days in the future
> I0716 21:01:30.737382 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000/executors/1e00dd3c-5c2d-4423-b6b6-74a0b90b7829' for gc 6.99999147223407days in the future
> I0716 21:01:30.737534 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000' for gc 6.99999147044148days in the future
> I0716 21:01:30.737673 8415 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleSlaves_9YD8Nc/meta/slaves/20140716-210126-1828659978-34280-8390-1/frameworks/20140716-210126-1828659978-34280-8390-0000' for gc 6.99999146960593days in the future
> I0716 21:01:30.738814 8424 slave.cpp:2331] master@<scrubbed_ip>:34280 exited
> W0716 21:01:30.738946 8424 slave.cpp:2334] Master disconnected! Waiting for a new master to be elected
> I0716 21:01:30.738848 8418 slave.cpp:2331] master@<scrubbed_ip>:34280 exited
> W0716 21:01:30.739051 8418 slave.cpp:2334] Master disconnected! Waiting for a new master to be elected
> I0716 21:01:30.746011 8390 slave.cpp:484] Slave terminating
> I0716 21:01:30.748245 8406 slave.cpp:484] Slave terminating
> I0716 21:01:30.753913 8413 cgroups.cpp:2021] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d
> I0716 21:01:30.755542 8416 cgroups.cpp:1375] Successfullly froze cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d after 1.540864ms
> I0716 21:01:30.757416 8410 cgroups.cpp:2038] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d
> I0716 21:01:30.759168 8426 cgroups.cpp:1404] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos_test_25b1ab5e-ab9b-4e62-b73c-7baf4840f05d after 1.659136ms
> I0716 21:01:30.768137 8427 cgroups.cpp:2021] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5
> I0716 21:01:30.769773 8421 cgroups.cpp:1375] Successfullly froze cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5 after 1.524992ms
> I0716 21:01:30.771571 8413 cgroups.cpp:2038] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5
> I0716 21:01:30.773157 8413 cgroups.cpp:1404] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos_test_d6bc5192-02b1-4fd0-b20c-1ba6014fa3e5 after 1.490944ms
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)