SlaveRecoveryTest.MultipleSlaves is flaky.

[ 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)