[
https://issues.apache.org/jira/browse/MESOS-1854?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Benjamin Mahler updated MESOS-1854:
-----------------------------------
Sprint: Mesos Q3 Sprint 6
> SlaveRecoveryTest.MultipleSlaves is flaky.
> ------------------------------------------
>
> Key: MESOS-1854
> URL: https://issues.apache.org/jira/browse/MESOS-1854
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Mahler
>
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2408/consoleFull
> {noformat}
> [ RUN ] SlaveRecoveryTest/0.MultipleSlaves
> Using temporary directory '/tmp/SlaveRecoveryTest_0_MultipleSlaves_yOuJDJ'
> I1001 01:25:43.585139 23806 leveldb.cpp:176] Opened db in 2.028599ms
> I1001 01:25:43.585713 23806 leveldb.cpp:183] Compacted db in 552764ns
> I1001 01:25:43.585731 23806 leveldb.cpp:198] Created db iterator in 3825ns
> I1001 01:25:43.585738 23806 leveldb.cpp:204] Seeked to beginning of db in
> 700ns
> I1001 01:25:43.585744 23806 leveldb.cpp:273] Iterated through 0 keys in the
> db in 370ns
> I1001 01:25:43.585759 23806 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1001 01:25:43.586006 23828 recover.cpp:425] Starting replica recovery
> I1001 01:25:43.586093 23828 recover.cpp:451] Replica is in EMPTY status
> I1001 01:25:43.586524 23828 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I1001 01:25:43.586606 23824 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I1001 01:25:43.586741 23831 recover.cpp:542] Updating replica status to
> STARTING
> I1001 01:25:43.586899 23825 master.cpp:312] Master
> 20141001-012543-3176252227-55929-23806 (proserpina.apache.org) started on
> 67.195.81.189:55929
> I1001 01:25:43.586930 23825 master.cpp:358] Master only allowing
> authenticated frameworks to register
> I1001 01:25:43.586942 23825 master.cpp:363] Master only allowing
> authenticated slaves to register
> I1001 01:25:43.586953 23825 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_yOuJDJ/credentials'
> I1001 01:25:43.587057 23825 master.cpp:392] Authorization enabled
> I1001 01:25:43.587241 23829 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I1001 01:25:43.587270 23828 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 484210ns
> I1001 01:25:43.587278 23823 hierarchical_allocator_process.hpp:299]
> Initializing hierarchical allocator process with master :
> master@67.195.81.189:55929
> I1001 01:25:43.587288 23828 replica.cpp:320] Persisted replica status to
> STARTING
> I1001 01:25:43.587393 23828 recover.cpp:451] Replica is in STARTING status
> I1001 01:25:43.587611 23825 master.cpp:1241] The newly elected leader is
> master@67.195.81.189:55929 with id 20141001-012543-3176252227-55929-23806
> I1001 01:25:43.587631 23825 master.cpp:1254] Elected as the leading master!
> I1001 01:25:43.587643 23825 master.cpp:1072] Recovering from registrar
> I1001 01:25:43.587704 23824 registrar.cpp:312] Recovering registrar
> I1001 01:25:43.587731 23827 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I1001 01:25:43.587937 23821 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I1001 01:25:43.588060 23827 recover.cpp:542] Updating replica status to VOTING
> I1001 01:25:43.588371 23830 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 143615ns
> I1001 01:25:43.588392 23830 replica.cpp:320] Persisted replica status to
> VOTING
> I1001 01:25:43.588433 23821 recover.cpp:556] Successfully joined the Paxos
> group
> I1001 01:25:43.588496 23821 recover.cpp:440] Recover process terminated
> I1001 01:25:43.588632 23820 log.cpp:656] Attempting to start the writer
> I1001 01:25:43.589174 23832 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1001 01:25:43.589617 23832 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 427035ns
> I1001 01:25:43.589630 23832 replica.cpp:342] Persisted promised to 1
> I1001 01:25:43.589833 23821 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I1001 01:25:43.590340 23821 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1001 01:25:43.590499 23821 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 142051ns
> I1001 01:25:43.590512 23821 replica.cpp:676] Persisted action at 0
> I1001 01:25:43.590903 23833 replica.cpp:508] Replica received write request
> for position 0
> I1001 01:25:43.590932 23833 leveldb.cpp:438] Reading position from leveldb
> took 14221ns
> I1001 01:25:43.591089 23833 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 140263ns
> I1001 01:25:43.591101 23833 replica.cpp:676] Persisted action at 0
> I1001 01:25:43.591346 23823 replica.cpp:655] Replica received learned notice
> for position 0
> I1001 01:25:43.591505 23823 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 141764ns
> I1001 01:25:43.591518 23823 replica.cpp:676] Persisted action at 0
> I1001 01:25:43.591526 23823 replica.cpp:661] Replica learned NOP action at
> position 0
> I1001 01:25:43.591713 23821 log.cpp:672] Writer started with ending position 0
> I1001 01:25:43.592037 23828 leveldb.cpp:438] Reading position from leveldb
> took 10708ns
> I1001 01:25:43.593158 23831 registrar.cpp:345] Successfully fetched the
> registry (0B)
> I1001 01:25:43.593184 23831 registrar.cpp:421] Attempting to update the
> 'registry'
> I1001 01:25:43.594137 23822 log.cpp:680] Attempting to append 143 bytes to
> the log
> I1001 01:25:43.594207 23826 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I1001 01:25:43.594784 23830 replica.cpp:508] Replica received write request
> for position 1
> I1001 01:25:43.595283 23830 leveldb.cpp:343] Persisting action (162 bytes) to
> leveldb took 471709ns
> I1001 01:25:43.595302 23830 replica.cpp:676] Persisted action at 1
> I1001 01:25:43.595554 23821 replica.cpp:655] Replica received learned notice
> for position 1
> I1001 01:25:43.595684 23821 leveldb.cpp:343] Persisting action (164 bytes) to
> leveldb took 105065ns
> I1001 01:25:43.595698 23821 replica.cpp:676] Persisted action at 1
> I1001 01:25:43.595706 23821 replica.cpp:661] Replica learned APPEND action at
> position 1
> I1001 01:25:43.596006 23830 registrar.cpp:478] Successfully updated 'registry'
> I1001 01:25:43.596038 23829 log.cpp:699] Attempting to truncate the log to 1
> I1001 01:25:43.596053 23830 registrar.cpp:371] Successfully recovered
> registrar
> I1001 01:25:43.596129 23824 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I1001 01:25:43.596175 23834 master.cpp:1099] Recovered 0 slaves from the
> Registry (105B) ; allowing 10mins for slaves to re-register
> I1001 01:25:43.596520 23820 replica.cpp:508] Replica received write request
> for position 2
> I1001 01:25:43.596626 23820 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 88093ns
> I1001 01:25:43.596639 23820 replica.cpp:676] Persisted action at 2
> I1001 01:25:43.596865 23821 replica.cpp:655] Replica received learned notice
> for position 2
> I1001 01:25:43.596979 23821 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 96148ns
> I1001 01:25:43.597020 23821 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 15831ns
> I1001 01:25:43.597030 23821 replica.cpp:676] Persisted action at 2
> I1001 01:25:43.597038 23821 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I1001 01:25:43.608242 23806 sched.cpp:137] Version: 0.21.0
> I1001 01:25:43.608459 23823 sched.cpp:233] New master detected at
> master@67.195.81.189:55929
> I1001 01:25:43.608489 23823 sched.cpp:283] Authenticating with master
> master@67.195.81.189:55929
> I1001 01:25:43.608558 23827 authenticatee.hpp:128] Creating new client SASL
> connection
> I1001 01:25:43.608667 23806 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I1001 01:25:43.608672 23828 master.cpp:3737] Authenticating
> scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:43.608796 23827 authenticator.hpp:156] Creating new server SASL
> connection
> I1001 01:25:43.609050 23824 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I1001 01:25:43.609076 23824 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1001 01:25:43.609169 23824 authenticator.hpp:262] Received SASL
> authentication start
> I1001 01:25:43.609218 23824 authenticator.hpp:384] Authentication requires
> more steps
> I1001 01:25:43.609313 23824 authenticatee.hpp:265] Received SASL
> authentication step
> I1001 01:25:43.609519 23832 authenticator.hpp:290] Received SASL
> authentication step
> I1001 01:25:43.609558 23832 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1001 01:25:43.609578 23832 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1001 01:25:43.609596 23832 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1001 01:25:43.609608 23832 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1001 01:25:43.609618 23832 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:43.609627 23832 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:43.609645 23832 authenticator.hpp:376] Authentication success
> I1001 01:25:43.609691 23832 authenticatee.hpp:305] Authentication success
> I1001 01:25:43.609740 23820 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at
> scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:43.609834 23832 sched.cpp:357] Successfully authenticated with
> master master@67.195.81.189:55929
> I1001 01:25:43.609863 23832 sched.cpp:476] Sending registration request to
> master@67.195.81.189:55929
> I1001 01:25:43.609928 23832 master.cpp:1360] Received registration request
> from scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:43.609966 23832 master.cpp:1320] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I1001 01:25:43.610122 23832 master.cpp:1419] Registering framework
> 20141001-012543-3176252227-55929-23806-0000 at
> scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:43.610261 23830 hierarchical_allocator_process.hpp:329] Added
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.610280 23830 hierarchical_allocator_process.hpp:697] No
> resources available to allocate!
> I1001 01:25:43.610291 23830 hierarchical_allocator_process.hpp:659] Performed
> allocation for 0 slaves in 11284ns
> I1001 01:25:43.610373 23829 sched.cpp:407] Framework registered with
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.610405 23829 sched.cpp:421] Scheduler::registered took 17695ns
> I1001 01:25:43.610553 23827 slave.cpp:169] Slave started on
> 97)@67.195.81.189:55929
> I1001 01:25:43.610580 23827 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/credential'
> I1001 01:25:43.610657 23827 slave.cpp:276] Slave using credential for:
> test-principal
> I1001 01:25:43.610752 23827 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1001 01:25:43.610806 23827 slave.cpp:317] Slave hostname:
> proserpina.apache.org
> I1001 01:25:43.610816 23827 slave.cpp:318] Slave checkpoint: true
> I1001 01:25:43.611578 23828 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta'
> I1001 01:25:43.611743 23823 status_update_manager.cpp:193] Recovering status
> update manager
> I1001 01:25:43.611831 23824 containerizer.cpp:252] Recovering containerizer
> I1001 01:25:43.612187 23821 slave.cpp:3271] Finished recovery
> I1001 01:25:43.612448 23835 slave.cpp:598] New master detected at
> master@67.195.81.189:55929
> I1001 01:25:43.612503 23835 slave.cpp:672] Authenticating with master
> master@67.195.81.189:55929
> I1001 01:25:43.612525 23824 status_update_manager.cpp:167] New master
> detected at master@67.195.81.189:55929
> I1001 01:25:43.612570 23835 slave.cpp:645] Detecting new master
> I1001 01:25:43.612596 23832 authenticatee.hpp:128] Creating new client SASL
> connection
> I1001 01:25:43.612685 23821 master.cpp:3737] Authenticating
> slave(97)@67.195.81.189:55929
> I1001 01:25:43.612746 23832 authenticator.hpp:156] Creating new server SASL
> connection
> I1001 01:25:43.612807 23830 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I1001 01:25:43.612826 23830 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1001 01:25:43.612896 23825 authenticator.hpp:262] Received SASL
> authentication start
> I1001 01:25:43.612931 23825 authenticator.hpp:384] Authentication requires
> more steps
> I1001 01:25:43.612962 23825 authenticatee.hpp:265] Received SASL
> authentication step
> I1001 01:25:43.613044 23825 authenticator.hpp:290] Received SASL
> authentication step
> I1001 01:25:43.613061 23825 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1001 01:25:43.613068 23825 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1001 01:25:43.613078 23825 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1001 01:25:43.613086 23825 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1001 01:25:43.613092 23825 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:43.613100 23825 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:43.613113 23825 authenticator.hpp:376] Authentication success
> I1001 01:25:43.613185 23821 authenticatee.hpp:305] Authentication success
> I1001 01:25:43.613199 23825 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(97)@67.195.81.189:55929
> I1001 01:25:43.613466 23831 slave.cpp:729] Successfully authenticated with
> master master@67.195.81.189:55929
> I1001 01:25:43.613525 23831 slave.cpp:992] Will retry registration in
> 5.583896ms if necessary
> I1001 01:25:43.613575 23824 master.cpp:2930] Registering slave at
> slave(97)@67.195.81.189:55929 (proserpina.apache.org) with id
> 20141001-012543-3176252227-55929-23806-0
> I1001 01:25:43.613694 23825 registrar.cpp:421] Attempting to update the
> 'registry'
> I1001 01:25:43.614859 23821 log.cpp:680] Attempting to append 323 bytes to
> the log
> I1001 01:25:43.614910 23820 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I1001 01:25:43.615218 23820 replica.cpp:508] Replica received write request
> for position 3
> I1001 01:25:43.615855 23820 leveldb.cpp:343] Persisting action (342 bytes) to
> leveldb took 619795ns
> I1001 01:25:43.615869 23820 replica.cpp:676] Persisted action at 3
> I1001 01:25:43.616154 23827 replica.cpp:655] Replica received learned notice
> for position 3
> I1001 01:25:43.616668 23827 leveldb.cpp:343] Persisting action (344 bytes) to
> leveldb took 496399ns
> I1001 01:25:43.616685 23827 replica.cpp:676] Persisted action at 3
> I1001 01:25:43.616698 23827 replica.cpp:661] Replica learned APPEND action at
> position 3
> I1001 01:25:43.617126 23822 registrar.cpp:478] Successfully updated 'registry'
> I1001 01:25:43.617213 23824 log.cpp:699] Attempting to truncate the log to 3
> I1001 01:25:43.617247 23820 master.cpp:2970] Registered slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:43.617286 23833 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I1001 01:25:43.617321 23820 master.cpp:4180] Adding slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I1001 01:25:43.617436 23827 slave.cpp:763] Registered with master
> master@67.195.81.189:55929; given slave ID
> 20141001-012543-3176252227-55929-23806-0
> I1001 01:25:43.617547 23825 hierarchical_allocator_process.hpp:442] Added
> slave 20141001-012543-3176252227-55929-23806-0 (proserpina.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I1001 01:25:43.617615 23827 slave.cpp:776] Checkpointing SlaveInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/slave.info'
> I1001 01:25:43.617619 23825 hierarchical_allocator_process.hpp:734] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-0 to framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.617707 23833 replica.cpp:508] Replica received write request
> for position 4
> I1001 01:25:43.617737 23825 hierarchical_allocator_process.hpp:679] Performed
> allocation for slave 20141001-012543-3176252227-55929-23806-0 in 144006ns
> I1001 01:25:43.617739 23827 slave.cpp:2345] Received ping from
> slave-observer(85)@67.195.81.189:55929
> I1001 01:25:43.617784 23823 master.hpp:868] Adding offer
> 20141001-012543-3176252227-55929-23806-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-0 (proserpina.apache.org)
> I1001 01:25:43.617825 23823 master.cpp:3679] Sending 1 offers to framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.617966 23824 sched.cpp:544] Scheduler::resourceOffers took
> 35312ns
> I1001 01:25:43.618227 23833 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 496093ns
> I1001 01:25:43.618249 23833 replica.cpp:676] Persisted action at 4
> I1001 01:25:43.618661 23826 replica.cpp:655] Replica received learned notice
> for position 4
> I1001 01:25:43.618798 23826 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 118995ns
> I1001 01:25:43.618824 23826 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 13403ns
> I1001 01:25:43.618834 23826 replica.cpp:676] Persisted action at 4
> I1001 01:25:43.618840 23826 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> I1001 01:25:43.619340 23830 master.hpp:877] Removing offer
> 20141001-012543-3176252227-55929-23806-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-0 (proserpina.apache.org)
> I1001 01:25:43.619381 23830 master.cpp:2274] Processing reply for offers: [
> 20141001-012543-3176252227-55929-23806-0 ] on slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org) for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.619410 23830 master.cpp:2357] Authorizing framework principal
> 'test-principal' to launch task 355d45f6-bcec-424c-93fd-0540d4e3b473 as user
> 'jenkins'
> I1001 01:25:43.619730 23824 master.hpp:845] Adding task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-0 (proserpina.apache.org)
> I1001 01:25:43.619758 23824 master.cpp:2423] Launching task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:43.619945 23834 slave.cpp:1023] Got assigned task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.620048 23834 slave.cpp:3620] Checkpointing FrameworkInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.info'
> I1001 01:25:43.620229 23834 slave.cpp:3627] Checkpointing framework pid
> 'scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.pid'
> I1001 01:25:43.620542 23834 slave.cpp:1133] Launching task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.622125 23834 slave.cpp:3943] Checkpointing ExecutorInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/executor.info'
> I1001 01:25:43.622606 23827 containerizer.cpp:394] Starting container
> '0392dc8a-af38-4e7c-bb3b-8e7b441c2269' for executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> '20141001-012543-3176252227-55929-23806-0000'
> I1001 01:25:43.622608 23834 slave.cpp:4053] Checkpointing TaskInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269/tasks/355d45f6-bcec-424c-93fd-0540d4e3b473/task.info'
> I1001 01:25:43.622859 23834 slave.cpp:1246] Queuing task
> '355d45f6-bcec-424c-93fd-0540d4e3b473' for executor
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> '20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:43.622978 23834 slave.cpp:554] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> I1001 01:25:43.623919 23827 launcher.cpp:137] Forked child with pid '26234'
> for container '0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> I1001 01:25:44.587775 23829 hierarchical_allocator_process.hpp:659] Performed
> allocation for 1 slaves in 44732ns
> I1001 01:25:45.827688 23827 containerizer.cpp:678] Checkpointing executor's
> forked pid 26234 to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269/pids/forked.pid'
> I1001 01:25:45.828328 23824 containerizer.cpp:510] Fetching URIs for
> container '0392dc8a-af38-4e7c-bb3b-8e7b441c2269' using command
> '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I1001 01:25:45.877245 23830 slave.cpp:2611] Monitoring executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> '20141001-012543-3176252227-55929-23806-0000' in container
> '0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1001 01:25:45.911231 26269 process.cpp:1671] libprocess is initialized on
> 67.195.81.189:47889 for 16 cpus
> I1001 01:25:45.911495 26269 logging.cpp:177] Logging to STDERR
> I1001 01:25:45.912361 26269 exec.cpp:132] Version: 0.21.0
> I1001 01:25:45.913002 26289 exec.cpp:182] Executor started at:
> executor(1)@67.195.81.189:47889 with pid 26269
> I1001 01:25:45.913539 23826 slave.cpp:1756] Got registration for executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000 from
> executor(1)@67.195.81.189:47889
> I1001 01:25:45.913590 23826 slave.cpp:1842] Checkpointing executor pid
> 'executor(1)@67.195.81.189:47889' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269/pids/libprocess.pid'
> I1001 01:25:45.914019 23826 slave.cpp:1875] Flushing queued task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 for executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.914327 26284 exec.cpp:206] Executor registered on slave
> 20141001-012543-3176252227-55929-23806-0
> I1001 01:25:45.915282 26284 exec.cpp:218] Executor::registered took 62242ns
> Registered executor on proserpina.apache.org
> I1001 01:25:45.915361 26284 exec.cpp:293] Executor asked to run task
> '355d45f6-bcec-424c-93fd-0540d4e3b473'
> I1001 01:25:45.915403 26284 exec.cpp:302] Executor::launchTask took 26910ns
> Starting task 355d45f6-bcec-424c-93fd-0540d4e3b473
> sh -c 'sleep 1000'
> Forked command at 26300
> I1001 01:25:45.916811 26288 exec.cpp:525] Executor sending status update
> TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.917217 23831 slave.cpp:2109] Handling status update
> TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 from
> executor(1)@67.195.81.189:47889
> I1001 01:25:45.917410 23821 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.917433 23821 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 355d45f6-bcec-424c-93fd-0540d4e3b473 of
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.917645 23821 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.918794 23821 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 to master@67.195.81.189:55929
> I1001 01:25:45.918920 23821 slave.cpp:2266] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.918938 23821 slave.cpp:2272] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for
> task 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 to executor(1)@67.195.81.189:47889
> I1001 01:25:45.918941 23826 master.cpp:3301] Forwarding status update
> TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.919006 23826 master.cpp:3273] Status update TASK_RUNNING
> (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 from slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:45.919138 23832 sched.cpp:635] Scheduler::statusUpdate took
> 16955ns
> I1001 01:25:45.919222 23832 master.cpp:2777] Forwarding status update
> acknowledgement 4b892fb6-d554-4a12-849e-9f82d25558d7 for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 to slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:45.919244 26289 exec.cpp:339] Executor received status update
> acknowledgement 4b892fb6-d554-4a12-849e-9f82d25558d7 for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.919399 23822 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.919430 23822 status_update_manager.hpp:342] Checkpointing ACK
> for status update TASK_RUNNING (UUID: 4b892fb6-d554-4a12-849e-9f82d25558d7)
> for task 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.920145 23822 slave.cpp:1696] Status update manager
> successfully handled status update acknowledgement (UUID:
> 4b892fb6-d554-4a12-849e-9f82d25558d7) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:45.920730 23806 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I1001 01:25:45.922762 23835 slave.cpp:169] Slave started on
> 98)@67.195.81.189:55929
> I1001 01:25:45.922782 23835 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/credential'
> I1001 01:25:45.922859 23835 slave.cpp:276] Slave using credential for:
> test-principal
> I1001 01:25:45.922950 23835 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1001 01:25:45.923029 23835 slave.cpp:317] Slave hostname:
> proserpina.apache.org
> I1001 01:25:45.923040 23835 slave.cpp:318] Slave checkpoint: true
> I1001 01:25:45.923425 23825 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta'
> I1001 01:25:45.923599 23821 status_update_manager.cpp:193] Recovering status
> update manager
> I1001 01:25:45.923753 23832 containerizer.cpp:252] Recovering containerizer
> I1001 01:25:45.924370 23821 slave.cpp:3271] Finished recovery
> I1001 01:25:45.924654 23829 slave.cpp:598] New master detected at
> master@67.195.81.189:55929
> I1001 01:25:46.828418 23828 hierarchical_allocator_process.hpp:659] Performed
> allocation for 1 slaves in 36923ns
> I1001 01:25:47.786815 23829 slave.cpp:672] Authenticating with master
> master@67.195.81.189:55929
> I1001 01:25:47.786885 23828 status_update_manager.cpp:167] New master
> detected at master@67.195.81.189:55929
> I1001 01:25:47.786926 23829 slave.cpp:645] Detecting new master
> I1001 01:25:47.786943 23828 authenticatee.hpp:128] Creating new client SASL
> connection
> I1001 01:25:47.787117 23829 master.cpp:3737] Authenticating
> slave(98)@67.195.81.189:55929
> I1001 01:25:47.787518 23832 authenticator.hpp:156] Creating new server SASL
> connection
> I1001 01:25:47.787636 23830 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I1001 01:25:47.787659 23830 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1001 01:25:47.787699 23830 authenticator.hpp:262] Received SASL
> authentication start
> I1001 01:25:47.787756 23830 authenticator.hpp:384] Authentication requires
> more steps
> I1001 01:25:47.787842 23823 authenticatee.hpp:265] Received SASL
> authentication step
> I1001 01:25:47.787935 23821 authenticator.hpp:290] Received SASL
> authentication step
> I1001 01:25:47.787973 23821 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1001 01:25:47.787988 23821 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1001 01:25:47.788007 23821 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1001 01:25:47.788017 23821 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1001 01:25:47.788024 23821 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:47.788029 23821 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:47.788041 23821 authenticator.hpp:376] Authentication success
> I1001 01:25:47.788096 23824 authenticatee.hpp:305] Authentication success
> I1001 01:25:47.788152 23820 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(98)@67.195.81.189:55929
> I1001 01:25:47.788252 23824 slave.cpp:729] Successfully authenticated with
> master master@67.195.81.189:55929
> I1001 01:25:47.788314 23824 slave.cpp:992] Will retry registration in
> 2.169536ms if necessary
> I1001 01:25:47.788360 23832 master.cpp:2930] Registering slave at
> slave(98)@67.195.81.189:55929 (proserpina.apache.org) with id
> 20141001-012543-3176252227-55929-23806-1
> I1001 01:25:47.788511 23827 registrar.cpp:421] Attempting to update the
> 'registry'
> I1001 01:25:47.789825 23830 log.cpp:680] Attempting to append 499 bytes to
> the log
> I1001 01:25:47.789950 23835 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 5
> I1001 01:25:47.790377 23830 replica.cpp:508] Replica received write request
> for position 5
> I1001 01:25:47.790684 23830 leveldb.cpp:343] Persisting action (518 bytes) to
> leveldb took 281958ns
> I1001 01:25:47.790704 23830 replica.cpp:676] Persisted action at 5
> I1001 01:25:47.790967 23830 replica.cpp:655] Replica received learned notice
> for position 5
> I1001 01:25:47.791553 23832 slave.cpp:992] Will retry registration in
> 11.075599ms if necessary
> I1001 01:25:47.791597 23830 leveldb.cpp:343] Persisting action (520 bytes) to
> leveldb took 607006ns
> I1001 01:25:47.791599 23829 master.cpp:2918] Ignoring register slave message
> from slave(98)@67.195.81.189:55929 (proserpina.apache.org) as admission is
> already in progress
> I1001 01:25:47.791628 23830 replica.cpp:676] Persisted action at 5
> I1001 01:25:47.791647 23830 replica.cpp:661] Replica learned APPEND action at
> position 5
> I1001 01:25:47.792105 23823 registrar.cpp:478] Successfully updated 'registry'
> I1001 01:25:47.792201 23827 log.cpp:699] Attempting to truncate the log to 5
> I1001 01:25:47.792268 23830 master.cpp:2970] Registered slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:47.792295 23826 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 6
> I1001 01:25:47.792297 23830 master.cpp:4180] Adding slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I1001 01:25:47.792423 23826 slave.cpp:763] Registered with master
> master@67.195.81.189:55929; given slave ID
> 20141001-012543-3176252227-55929-23806-1
> I1001 01:25:47.792541 23825 hierarchical_allocator_process.hpp:442] Added
> slave 20141001-012543-3176252227-55929-23806-1 (proserpina.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I1001 01:25:47.792651 23825 hierarchical_allocator_process.hpp:734] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-1 to framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.792680 23820 replica.cpp:508] Replica received write request
> for position 6
> I1001 01:25:47.792680 23826 slave.cpp:776] Checkpointing SlaveInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/slave.info'
> I1001 01:25:47.792824 23825 hierarchical_allocator_process.hpp:679] Performed
> allocation for slave 20141001-012543-3176252227-55929-23806-1 in 217563ns
> I1001 01:25:47.792868 23826 slave.cpp:2345] Received ping from
> slave-observer(86)@67.195.81.189:55929
> I1001 01:25:47.792878 23820 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 162694ns
> I1001 01:25:47.792904 23820 replica.cpp:676] Persisted action at 6
> I1001 01:25:47.792891 23831 master.hpp:868] Adding offer
> 20141001-012543-3176252227-55929-23806-1 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-1 (proserpina.apache.org)
> I1001 01:25:47.792969 23831 master.cpp:3679] Sending 1 offers to framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.793257 23826 sched.cpp:544] Scheduler::resourceOffers took
> 75760ns
> I1001 01:25:47.793313 23824 replica.cpp:655] Replica received learned notice
> for position 6
> I1001 01:25:47.793800 23824 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 463031ns
> I1001 01:25:47.793836 23824 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 18549ns
> I1001 01:25:47.793849 23824 replica.cpp:676] Persisted action at 6
> I1001 01:25:47.793860 23824 replica.cpp:661] Replica learned TRUNCATE action
> at position 6
> I1001 01:25:47.795030 23823 master.hpp:877] Removing offer
> 20141001-012543-3176252227-55929-23806-1 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-1 (proserpina.apache.org)
> I1001 01:25:47.795106 23823 master.cpp:2274] Processing reply for offers: [
> 20141001-012543-3176252227-55929-23806-1 ] on slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org) for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.795169 23823 master.cpp:2357] Authorizing framework principal
> 'test-principal' to launch task ea9853fd-823f-49db-850c-9c24b546adc9 as user
> 'jenkins'
> I1001 01:25:47.795706 23827 master.hpp:845] Adding task
> ea9853fd-823f-49db-850c-9c24b546adc9 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-1 (proserpina.apache.org)
> I1001 01:25:47.795753 23827 master.cpp:2423] Launching task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:47.847157 23827 slave.cpp:1023] Got assigned task
> ea9853fd-823f-49db-850c-9c24b546adc9 for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.847237 23827 slave.cpp:3620] Checkpointing FrameworkInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.info'
> I1001 01:25:47.847386 23827 slave.cpp:3627] Checkpointing framework pid
> 'scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.pid'
> I1001 01:25:47.847654 23827 slave.cpp:1133] Launching task
> ea9853fd-823f-49db-850c-9c24b546adc9 for framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.848750 23827 slave.cpp:3943] Checkpointing ExecutorInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/executor.info'
> I1001 01:25:47.849167 23827 slave.cpp:4053] Checkpointing TaskInfo to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca/tasks/ea9853fd-823f-49db-850c-9c24b546adc9/task.info'
> I1001 01:25:47.849247 23825 containerizer.cpp:394] Starting container
> 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca' for executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> '20141001-012543-3176252227-55929-23806-0000'
> I1001 01:25:47.849308 23827 slave.cpp:1246] Queuing task
> 'ea9853fd-823f-49db-850c-9c24b546adc9' for executor
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> '20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:47.849412 23827 slave.cpp:554] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> I1001 01:25:47.850569 23833 launcher.cpp:137] Forked child with pid '26302'
> for container 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> I1001 01:25:47.850844 23833 containerizer.cpp:678] Checkpointing executor's
> forked pid 26302 to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca/pids/forked.pid'
> I1001 01:25:47.851541 23832 containerizer.cpp:510] Fetching URIs for
> container 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca' using command
> '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I1001 01:25:47.993482 23822 slave.cpp:2611] Monitoring executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> '20141001-012543-3176252227-55929-23806-0000' in container
> 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1001 01:25:48.026886 26337 process.cpp:1671] libprocess is initialized on
> 67.195.81.189:37911 for 16 cpus
> I1001 01:25:48.027199 26337 logging.cpp:177] Logging to STDERR
> I1001 01:25:48.028113 26337 exec.cpp:132] Version: 0.21.0
> I1001 01:25:48.028877 26354 exec.cpp:182] Executor started at:
> executor(1)@67.195.81.189:37911 with pid 26337
> I1001 01:25:48.029741 23826 slave.cpp:1756] Got registration for executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000 from
> executor(1)@67.195.81.189:37911
> I1001 01:25:48.029801 23826 slave.cpp:1842] Checkpointing executor pid
> 'executor(1)@67.195.81.189:37911' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca/pids/libprocess.pid'
> I1001 01:25:48.030307 23826 slave.cpp:1875] Flushing queued task
> ea9853fd-823f-49db-850c-9c24b546adc9 for executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.030683 26364 exec.cpp:206] Executor registered on slave
> 20141001-012543-3176252227-55929-23806-1
> I1001 01:25:48.031561 26364 exec.cpp:218] Executor::registered took 76997ns
> I1001 01:25:48.031635 26364 exec.cpp:293] Executor asked to run task
> 'ea9853fd-823f-49db-850c-9c24b546adc9'
> IRegistered executor on proserpina.apache.org
> 1001 01:25:48.031666 26364 exec.cpp:302] Executor::launchTask took 19006ns
> Starting task ea9853fd-823f-49db-850c-9c24b546adc9
> sh -c 'sleep 1000'
> Forked command at 26368
> I1001 01:25:48.033987 26358 exec.cpp:525] Executor sending status update
> TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.034378 23821 slave.cpp:2109] Handling status update
> TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 from
> executor(1)@67.195.81.189:37911
> I1001 01:25:48.034572 23822 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.034593 23822 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task ea9853fd-823f-49db-850c-9c24b546adc9 of
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.034786 23822 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.036030 23822 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 to master@67.195.81.189:55929
> I1001 01:25:48.036128 23822 slave.cpp:2266] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.036141 23822 slave.cpp:2272] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for
> task ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 to executor(1)@67.195.81.189:37911
> I1001 01:25:48.036236 23823 master.cpp:3301] Forwarding status update
> TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.036300 23823 master.cpp:3273] Status update TASK_RUNNING
> (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 from slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.036398 23823 sched.cpp:635] Scheduler::statusUpdate took
> 17268ns
> I1001 01:25:48.036438 26362 exec.cpp:339] Executor received status update
> acknowledgement 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4 for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.036594 23829 master.cpp:2777] Forwarding status update
> acknowledgement 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4 for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 to slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.036732 23829 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.036761 23829 status_update_manager.hpp:342] Checkpointing ACK
> for status update TASK_RUNNING (UUID: 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4)
> for task ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.037601 23829 slave.cpp:1696] Status update manager
> successfully handled status update acknowledgement (UUID:
> 29ac4e0f-a9af-4dd3-b348-a1511a03a0d4) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.038074 23824 slave.cpp:477] Slave terminating
> I1001 01:25:48.038189 23824 master.cpp:817] Slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org) disconnected
> I1001 01:25:48.038208 23824 master.cpp:1742] Disconnecting slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.038311 23824 master.cpp:1761] Deactivating slave
> 20141001-012543-3176252227-55929-23806-0 at slave(97)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.038411 23822 hierarchical_allocator_process.hpp:481] Slave
> 20141001-012543-3176252227-55929-23806-0 deactivated
> I1001 01:25:48.039829 23806 slave.cpp:477] Slave terminating
> I1001 01:25:48.039934 23826 master.cpp:817] Slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org) disconnected
> I1001 01:25:48.039964 23826 master.cpp:1742] Disconnecting slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.040144 23826 master.cpp:1761] Deactivating slave
> 20141001-012543-3176252227-55929-23806-1 at slave(98)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.040419 23833 hierarchical_allocator_process.hpp:481] Slave
> 20141001-012543-3176252227-55929-23806-1 deactivated
> I1001 01:25:48.041187 23806 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I1001 01:25:48.043272 23830 slave.cpp:169] Slave started on
> 99)@67.195.81.189:55929
> I1001 01:25:48.043308 23830 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/credential'
> I1001 01:25:48.043404 23806 containerizer.cpp:89] Using isolation:
> posix/cpu,posix/mem
> I1001 01:25:48.043414 23830 slave.cpp:276] Slave using credential for:
> test-principal
> I1001 01:25:48.043519 23830 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1001 01:25:48.043633 23830 slave.cpp:317] Slave hostname:
> proserpina.apache.org
> I1001 01:25:48.043648 23830 slave.cpp:318] Slave checkpoint: true
> I1001 01:25:48.044234 23833 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta'
> I1001 01:25:48.045552 23832 slave.cpp:3342] Recovering framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.045580 23832 slave.cpp:3786] Recovering executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.045786 23829 slave.cpp:169] Slave started on
> 100)@67.195.81.189:55929
> I1001 01:25:48.045814 23829 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/credential'
> I1001 01:25:48.045997 23829 slave.cpp:276] Slave using credential for:
> test-principal
> I1001 01:25:48.046136 23829 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1001 01:25:48.046212 23829 slave.cpp:317] Slave hostname:
> proserpina.apache.org
> I1001 01:25:48.046226 23829 slave.cpp:318] Slave checkpoint: true
> I1001 01:25:48.046293 23823 status_update_manager.cpp:193] Recovering status
> update manager
> I1001 01:25:48.046309 23823 status_update_manager.cpp:201] Recovering
> executor '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.046334 23823 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 355d45f6-bcec-424c-93fd-0540d4e3b473 of
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.046423 23832 slave.cpp:554] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> I1001 01:25:48.046447 23823 status_update_manager.hpp:306] Replaying status
> update stream for task 355d45f6-bcec-424c-93fd-0540d4e3b473
> I1001 01:25:48.046731 23821 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta'
> I1001 01:25:48.046844 23834 containerizer.cpp:252] Recovering containerizer
> I1001 01:25:48.046883 23834 containerizer.cpp:294] Recovering container
> '0392dc8a-af38-4e7c-bb3b-8e7b441c2269' for executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.047765 23830 slave.cpp:3212] Sending reconnect request to
> executor 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 at executor(1)@67.195.81.189:47889
> I1001 01:25:48.048192 23826 slave.cpp:3342] Recovering framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.048214 23826 slave.cpp:3786] Recovering executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.048280 26295 exec.cpp:252] Received reconnect request from
> slave 20141001-012543-3176252227-55929-23806-0
> I1001 01:25:48.048563 23829 status_update_manager.cpp:193] Recovering status
> update manager
> I1001 01:25:48.048585 23829 status_update_manager.cpp:201] Recovering
> executor 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.048602 23827 slave.cpp:1935] Re-registering executor
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.048619 23829 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task ea9853fd-823f-49db-850c-9c24b546adc9 of
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.048696 23826 slave.cpp:554] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> I1001 01:25:48.048758 23829 status_update_manager.hpp:306] Replaying status
> update stream for task ea9853fd-823f-49db-850c-9c24b546adc9
> I1001 01:25:48.048830 26297 exec.cpp:229] Executor re-registered on slave
> 20141001-012543-3176252227-55929-23806-0
> I1001 01:25:48.049095 23834 containerizer.cpp:252] Recovering containerizer
> I1001 01:25:48.049124 23834 containerizer.cpp:294] Recovering container
> 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca' for executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> IRe-registered executor on proserpina.apache.org
> 1001 01:25:48.050009 23832 slave.cpp:3212] Sending reconnect request to
> executor ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 at executor(1)@67.195.81.189:37911
> I1001 01:25:48.050019 26297 exec.cpp:241] Executor::reregistered took 40764ns
> II1001 01:25:48.050359 26366 exec.cpp:252] Received reconnect request from
> slave 20141001-012543-3176252227-55929-23806-1
> 1001 01:25:48.076720 23825 master.cpp:120] No whitelist given. Advertising
> offers for all slaves
> I1001 01:25:48.076809 23835 hierarchical_allocator_process.hpp:659] Performed
> allocation for 2 slaves in 10625ns
> I1001 01:25:48.076865 23834 slave.cpp:2058] Cleaning up un-reregistered
> executors
> I1001 01:25:48.085649 23834 slave.cpp:2076] Killing un-reregistered executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.076951 23828 slave.cpp:2058] Cleaning up un-reregistered
> executors
> I1001 01:25:48.085721 23834 slave.cpp:3271] Finished recovery
> I1001 01:25:48.085753 23828 slave.cpp:3271] Finished recovery
> I1001 01:25:48.085801 23826 containerizer.cpp:882] Destroying container
> 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> W1001 01:25:48.086422 23834 slave.cpp:1928] Shutting down executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000 because the slave is not in
> recovery mode
> I1001 01:25:48.086478 23825 slave.cpp:598] New master detected at
> master@67.195.81.189:55929
> I1001 01:25:48.086731 23825 slave.cpp:672] Authenticating with master
> master@67.195.81.189:55929
> I1001 01:25:48.086750 23834 slave.cpp:598] New master detected at
> master@67.195.81.189:55929
> I1001 01:25:48.086761 23833 status_update_manager.cpp:167] New master
> detected at master@67.195.81.189:55929
> I1001 01:25:48.086832 23825 slave.cpp:645] Detecting new master
> I1001 01:25:48.086839 26356 exec.cpp:379] Executor asked to shutdown
> I1001 01:25:48.086874 23832 authenticatee.hpp:128] Creating new client SASL
> connection
> II1001 01:25:48.086894 26356 exec.cpp:394] Executor::shutdown took 6002ns
> 1001 01:25:48.086889 23834 slave.cpp:672] Authenticating with master
> master@67.195.81.189:55929
> I1001 01:25:48.086951 26356 exec.cpp:78] Scheduling shutdown of the executor
> Shutting down
> ISending SIGTERM to process tree at pid 26368
> 1001 01:25:48.086967 23828 status_update_manager.cpp:167] New master detected
> at master@67.195.81.189:55929
> I1001 01:25:48.087021 23820 master.cpp:3737] Authenticating
> slave(99)@67.195.81.189:55929
> I1001 01:25:48.087086 23834 slave.cpp:645] Detecting new master
> I1001 01:25:48.087126 23821 authenticatee.hpp:128] Creating new client SASL
> connection
> I1001 01:25:48.087195 23823 authenticator.hpp:156] Creating new server SASL
> connection
> I1001 01:25:48.087236 23820 master.cpp:3737] Authenticating
> slave(100)@67.195.81.189:55929
> I1001 01:25:48.087271 23823 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I1001 01:25:48.087292 23823 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1001 01:25:48.087358 23834 authenticator.hpp:262] Received SASL
> authentication start
> I1001 01:25:48.087390 23829 authenticator.hpp:156] Creating new server SASL
> connection
> I1001 01:25:48.087424 23834 authenticator.hpp:384] Authentication requires
> more steps
> I1001 01:25:48.087491 23823 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I1001 01:25:48.087507 23823 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1001 01:25:48.087574 23822 authenticatee.hpp:265] Received SASL
> authentication step
> I1001 01:25:48.087597 23834 authenticator.hpp:262] Received SASL
> authentication start
> I1001 01:25:48.087648 23822 authenticator.hpp:290] Received SASL
> authentication step
> I1001 01:25:48.087656 23834 authenticator.hpp:384] Authentication requires
> more steps
> I1001 01:25:48.087682 23822 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1001 01:25:48.087695 23822 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1001 01:25:48.087710 23822 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1001 01:25:48.087728 23833 authenticatee.hpp:265] Received SASL
> authentication step
> I1001 01:25:48.087733 23822 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1001 01:25:48.153749 23822 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:48.153766 23822 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:48.153789 23822 authenticator.hpp:376] Authentication success
> I1001 01:25:48.087779 23833 authenticator.hpp:290] Received SASL
> authentication step
> I1001 01:25:48.153841 23822 authenticatee.hpp:305] Authentication success
> I1001 01:25:48.153858 23833 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1001 01:25:48.153872 23833 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1001 01:25:48.153868 23822 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(99)@67.195.81.189:55929
> I1001 01:25:48.153892 23833 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1001 01:25:48.153902 23833 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'proserpina.apache.org' server FQDN:
> 'proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1001 01:25:48.153908 23833 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:48.153915 23833 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1001 01:25:48.153928 23833 authenticator.hpp:376] Authentication success
> I1001 01:25:48.153965 23821 slave.cpp:729] Successfully authenticated with
> master master@67.195.81.189:55929
> I1001 01:25:48.154011 23820 authenticatee.hpp:305] Authentication success
> I1001 01:25:48.154079 23830 master.cpp:3777] Successfully authenticated
> principal 'test-principal' at slave(100)@67.195.81.189:55929
> I1001 01:25:48.154105 23821 slave.cpp:992] Will retry registration in
> 17.00359ms if necessary
> I1001 01:25:48.154711 23835 slave.cpp:729] Successfully authenticated with
> master master@67.195.81.189:55929
> I1001 01:25:48.154774 23835 slave.cpp:992] Will retry registration in
> 7.534964ms if necessary
> W1001 01:25:48.154861 23830 master.cpp:3045] Slave at
> slave(99)@67.195.81.189:55929 (proserpina.apache.org) is being allowed to
> re-register with an already in use id
> (20141001-012543-3176252227-55929-23806-0)
> W1001 01:25:48.155035 23830 master.cpp:3045] Slave at
> slave(100)@67.195.81.189:55929 (proserpina.apache.org) is being allowed to
> re-register with an already in use id
> (20141001-012543-3176252227-55929-23806-1)
> I1001 01:25:48.155061 23825 slave.cpp:825] Re-registered with master
> master@67.195.81.189:55929
> I1001 01:25:48.155182 23820 slave.cpp:825] Re-registered with master
> master@67.195.81.189:55929
> I1001 01:25:48.155220 23830 hierarchical_allocator_process.hpp:495] Slave
> 20141001-012543-3176252227-55929-23806-0 reactivated
> I1001 01:25:48.155300 23825 slave.cpp:1606] Updating framework
> 20141001-012543-3176252227-55929-23806-0000 pid to
> scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:48.155349 23825 slave.cpp:1614] Checkpointing framework pid
> 'scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.pid'
> I1001 01:25:48.155473 23820 slave.cpp:1606] Updating framework
> 20141001-012543-3176252227-55929-23806-0000 pid to
> scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929
> I1001 01:25:48.155496 23830 hierarchical_allocator_process.hpp:495] Slave
> 20141001-012543-3176252227-55929-23806-1 reactivated
> I1001 01:25:48.155519 23820 slave.cpp:1614] Checkpointing framework pid
> 'scheduler-4b05046d-6a57-40f5-be0c-18bc28c6b4a5@67.195.81.189:55929' to
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/framework.pid'
> I1001 01:25:48.177585 23830 containerizer.cpp:997] Executor for container
> 'd7f647b9-5ab4-4d53-bdba-dbb5252991ca' has exited
> I1001 01:25:48.177784 23827 master.cpp:2600] Asked to kill task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.177814 23827 master.cpp:2697] Telling slave
> 20141001-012543-3176252227-55929-23806-0 at slave(99)@67.195.81.189:55929
> (proserpina.apache.org) to kill task 355d45f6-bcec-424c-93fd-0540d4e3b473 of
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.178264 23834 slave.cpp:2669] Executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000 terminated with signal Killed
> I1001 01:25:48.178284 23830 slave.cpp:1301] Asked to kill task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.178311 23827 master.cpp:2600] Asked to kill task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.178331 23827 master.cpp:2697] Telling slave
> 20141001-012543-3176252227-55929-23806-1 at slave(100)@67.195.81.189:55929
> (proserpina.apache.org) to kill task ea9853fd-823f-49db-850c-9c24b546adc9 of
> framework 20141001-012543-3176252227-55929-23806-0000
> E1001 01:25:48.178405 23825 slave.cpp:2939] Failed to unmonitor container for
> executor ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000: Not monitored
> I1001 01:25:48.178576 26292 exec.cpp:313] Executor asked to kill task
> '355d45f6-bcec-424c-93fd-0540d4e3b473'
> IShutting down
> 1001 01:25:48.178611 26292 exec.cpp:322] Executor::killTask took 15189ns
> Sending SIGTERM to process tree at pid 26300
> I1001 01:25:48.179136 23834 slave.cpp:2109] Handling status update
> TASK_FAILED (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 from @0.0.0.0:0
> I1001 01:25:48.179163 23834 slave.cpp:3989] Terminating task
> ea9853fd-823f-49db-850c-9c24b546adc9
> I1001 01:25:48.179266 23834 slave.cpp:1301] Asked to kill task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> W1001 01:25:48.179278 23834 slave.cpp:1386] Ignoring kill task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 because the executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' is terminating/terminated
> W1001 01:25:48.179299 23827 containerizer.cpp:788] Ignoring update for
> unknown container: d7f647b9-5ab4-4d53-bdba-dbb5252991ca
> I1001 01:25:48.179441 23822 status_update_manager.cpp:320] Received status
> update TASK_FAILED (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.179463 23822 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_FAILED (UUID:
> 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.180361 23822 status_update_manager.cpp:373] Forwarding status
> update TASK_FAILED (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 to master@67.195.81.189:55929
> I1001 01:25:48.180461 23822 slave.cpp:2266] Status update manager
> successfully handled status update TASK_FAILED (UUID:
> 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.180474 23835 master.cpp:3301] Forwarding status update
> TASK_FAILED (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.220652 23835 master.cpp:3273] Status update TASK_FAILED (UUID:
> 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 from slave
> 20141001-012543-3176252227-55929-23806-1 at slave(100)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.220832 23822 sched.cpp:635] Scheduler::statusUpdate took
> 21039ns
> I1001 01:25:48.221012 23835 hierarchical_allocator_process.hpp:563] Recovered
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
> allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
> slave 20141001-012543-3176252227-55929-23806-1 from framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.221099 23820 master.cpp:4485] Removing task
> ea9853fd-823f-49db-850c-9c24b546adc9 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] of framework
> 20141001-012543-3176252227-55929-23806-0000 on slave
> 20141001-012543-3176252227-55929-23806-1 at slave(100)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.221169 23820 master.cpp:2777] Forwarding status update
> acknowledgement 52504af1-d096-48e1-921c-1d3faa5bd414 for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000 to slave
> 20141001-012543-3176252227-55929-23806-1 at slave(100)@67.195.81.189:55929
> (proserpina.apache.org)
> I1001 01:25:48.221271 23820 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.221292 23820 status_update_manager.hpp:342] Checkpointing ACK
> for status update TASK_FAILED (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414)
> for task ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> ../../src/tests/slave_recovery_tests.cpp:3154: Failure
> Value of: status1.get().state()
> Actual: TASK_FAILED
> Expected: TASK_KILLED
> I1001 01:25:48.221699 23829 master.cpp:767] Framework
> 20141001-012543-3176252227-55929-23806-0000 disconnected
> I1001 01:25:48.221719 23829 master.cpp:1705] Disconnecting framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.221730 23829 master.cpp:1721] Deactivating framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.221752 23829 master.cpp:789] Giving framework
> 20141001-012543-3176252227-55929-23806-0000 0ns to failover
> ../../src/tests/slave_recovery_tests.cpp:3135: Failure
> Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(_,
> _))...
> Expected: to be called at least twice
> Actual: called once - unsatisfied and active
> I1001 01:25:48.221961 23822 hierarchical_allocator_process.hpp:405]
> Deactivated framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.221992 23820 status_update_manager.cpp:530] Cleaning up status
> update stream for task ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222017 23833 master.cpp:3549] Framework failover timeout,
> removing framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222033 23833 master.cpp:4041] Removing framework
> 20141001-012543-3176252227-55929-23806-0000
> W1001 01:25:48.222069 23833 master.cpp:4471] Removing task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] of framework
> 20141001-012543-3176252227-55929-23806-0000 on slave
> 20141001-012543-3176252227-55929-23806-0 at slave(99)@67.195.81.189:55929
> (proserpina.apache.org) in non-terminal state TASK_RUNNING
> I1001 01:25:48.222105 23820 slave.cpp:1429] Asked to shut down framework
> 20141001-012543-3176252227-55929-23806-0000 by master@67.195.81.189:55929
> I1001 01:25:48.222126 23820 slave.cpp:1454] Shutting down framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222146 23820 slave.cpp:2805] Cleaning up executor
> 'ea9853fd-823f-49db-850c-9c24b546adc9' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222158 23821 slave.cpp:1429] Asked to shut down framework
> 20141001-012543-3176252227-55929-23806-0000 by master@67.195.81.189:55929
> I1001 01:25:48.222178 23821 slave.cpp:1454] Shutting down framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222192 23821 slave.cpp:2951] Shutting down executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222244 23835 hierarchical_allocator_process.hpp:563] Recovered
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
> allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
> slave 20141001-012543-3176252227-55929-23806-0 from framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222314 23835 hierarchical_allocator_process.hpp:360] Removed
> framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222352 23820 slave.cpp:2880] Cleaning up framework
> 20141001-012543-3176252227-55929-23806-0000
> Killing the following process trees:
> [
> -+- 26300 sh -c sleep 1000
> \--- 26301 sleep 1000
> ]
> I1001 01:25:48.222440 26292 exec.cpp:379] Executor asked to shutdown
> I1001 01:25:48.222463 23823 status_update_manager.cpp:282] Closing status
> update streams for framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222483 26292 exec.cpp:394] Executor::shutdown took 4074ns
> I1001 01:25:48.222491 23833 master.cpp:676] Master terminating
> II1001 01:25:48.222513 26292 exec.cpp:78] Scheduling shutdown of the executor
> 1001 01:25:48.222508 23820 slave.cpp:1696] Status update manager successfully
> handled status update acknowledgement (UUID:
> 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of framework
> 20141001-012543-3176252227-55929-23806-0000
> Shutting down
> E1001 01:25:48.222525 23820 slave.cpp:1707] Status update acknowledgement
> (UUID: 52504af1-d096-48e1-921c-1d3faa5bd414) for task
> ea9853fd-823f-49db-850c-9c24b546adc9 of unknown framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.222548 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> for gc 6.99999742775407days in the future
> I1001 01:25:48.222645 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9'
> for gc 6.9999974273037days in the future
> I1001 01:25:48.222673 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9/runs/d7f647b9-5ab4-4d53-bdba-dbb5252991ca'
> for gc 6.99999742689778days in the future
> I1001 01:25:48.222698 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/ea9853fd-823f-49db-850c-9c24b546adc9'
> for gc 6.99999742664296days in the future
> I1001 01:25:48.222722 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000'
> for gc 6.99999742605333days in the future
> I1001 01:25:48.222749 23826 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_PYyzeA/meta/slaves/20141001-012543-3176252227-55929-23806-1/frameworks/20141001-012543-3176252227-55929-23806-0000'
> for gc 6.99999742583407days in the future
> I1001 01:25:48.222803 23826 slave.cpp:2430] master@67.195.81.189:55929 exited
> Command terminated with signal Terminated (pid: 26300)
> I1001 01:25:48.222811 23832 slave.cpp:2430] master@67.195.81.189:55929 exited
> W1001 01:25:48.285262 23826 slave.cpp:2433] Master disconnected! Waiting for
> a new master to be elected
> I1001 01:25:48.285280 23826 slave.cpp:477] Slave terminating
> W1001 01:25:48.285282 23832 slave.cpp:2433] Master disconnected! Waiting for
> a new master to be elected
> I1001 01:25:48.286417 26291 exec.cpp:525] Executor sending status update
> TASK_KILLED (UUID: d6585bb8-9345-4f0e-a09e-c5dcc8faa456) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.286676 23831 containerizer.cpp:882] Destroying container
> '0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> I1001 01:25:48.286790 23833 slave.cpp:2109] Handling status update
> TASK_KILLED (UUID: d6585bb8-9345-4f0e-a09e-c5dcc8faa456) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 from
> executor(1)@67.195.81.189:47889
> W1001 01:25:48.286811 23833 slave.cpp:2133] Ignoring status update
> TASK_KILLED (UUID: d6585bb8-9345-4f0e-a09e-c5dcc8faa456) for task
> 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000 for terminating framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.379730 23826 containerizer.cpp:997] Executor for container
> '0392dc8a-af38-4e7c-bb3b-8e7b441c2269' has exited
> I1001 01:25:48.380717 23824 slave.cpp:2669] Executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000 terminated with signal Killed
> I1001 01:25:48.380816 23824 slave.cpp:2805] Cleaning up executor
> '355d45f6-bcec-424c-93fd-0540d4e3b473' of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.381057 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> for gc 6.99999559108741days in the future
> I1001 01:25:48.381094 23824 slave.cpp:2880] Cleaning up framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.381115 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473'
> for gc 6.99999558988444days in the future
> I1001 01:25:48.381165 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473/runs/0392dc8a-af38-4e7c-bb3b-8e7b441c2269'
> for gc 6.99999558952593days in the future
> I1001 01:25:48.381181 23823 status_update_manager.cpp:282] Closing status
> update streams for framework 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.381189 23824 slave.cpp:477] Slave terminating
> I1001 01:25:48.381202 23823 status_update_manager.cpp:530] Cleaning up status
> update stream for task 355d45f6-bcec-424c-93fd-0540d4e3b473 of framework
> 20141001-012543-3176252227-55929-23806-0000
> I1001 01:25:48.381201 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000/executors/355d45f6-bcec-424c-93fd-0540d4e3b473'
> for gc 6.99999558929481days in the future
> I1001 01:25:48.381237 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000'
> for gc 6.99999558861037days in the future
> I1001 01:25:48.381299 23820 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_MultipleSlaves_euOnUB/meta/slaves/20141001-012543-3176252227-55929-23806-0/frameworks/20141001-012543-3176252227-55929-23806-0000'
> for gc 6.99999558828741days in the future
> [ FAILED ] SlaveRecoveryTest/0.MultipleSlaves, where TypeParam =
> mesos::internal::slave::MesosContainerizer (4801 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
