You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Cody Maloney (JIRA)" <ji...@apache.org> on 2014/12/04 22:27:12 UTC
[jira] [Updated] (MESOS-1545)
SlaveRecoveryTest/0.MultipleFrameworks is flaky
[ https://issues.apache.org/jira/browse/MESOS-1545?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Cody Maloney updated MESOS-1545:
--------------------------------
Labels: flaky (was: )
> SlaveRecoveryTest/0.MultipleFrameworks is flaky
> -----------------------------------------------
>
> Key: MESOS-1545
> URL: https://issues.apache.org/jira/browse/MESOS-1545
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Labels: flaky
>
> {code}
> [ RUN ] SlaveRecoveryTest/0.MultipleFrameworks
> Using temporary directory '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_6dJqxr'
> I0626 00:04:39.557339 5450 leveldb.cpp:176] Opened db in 179.857593ms
> I0626 00:04:39.565433 5450 leveldb.cpp:183] Compacted db in 8.071041ms
> I0626 00:04:39.565457 5450 leveldb.cpp:198] Created db iterator in 4065ns
> I0626 00:04:39.565466 5450 leveldb.cpp:204] Seeked to beginning of db in 596ns
> I0626 00:04:39.565474 5450 leveldb.cpp:273] Iterated through 0 keys in the db in 396ns
> I0626 00:04:39.565490 5450 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0626 00:04:39.565827 5476 recover.cpp:425] Starting replica recovery
> I0626 00:04:39.566033 5474 recover.cpp:451] Replica is in EMPTY status
> I0626 00:04:39.566504 5474 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0626 00:04:39.566686 5477 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0626 00:04:39.566905 5472 recover.cpp:542] Updating replica status to STARTING
> I0626 00:04:39.568307 5471 master.cpp:288] Master 20140626-000439-1032504131-55423-5450 (juno.apache.org) started on 67.195.138.61:55423
> I0626 00:04:39.568332 5471 master.cpp:325] Master only allowing authenticated frameworks to register
> I0626 00:04:39.568339 5471 master.cpp:330] Master only allowing authenticated slaves to register
> I0626 00:04:39.568348 5471 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_6dJqxr/credentials'
> I0626 00:04:39.568461 5471 master.cpp:356] Authorization enabled
> I0626 00:04:39.568739 5478 master.cpp:122] No whitelist given. Advertising offers for all slaves
> I0626 00:04:39.568814 5475 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@67.195.138.61:55423
> I0626 00:04:39.569206 5478 master.cpp:1122] The newly elected leader is master@67.195.138.61:55423 with id 20140626-000439-1032504131-55423-5450
> I0626 00:04:39.569223 5478 master.cpp:1135] Elected as the leading master!
> I0626 00:04:39.569231 5478 master.cpp:953] Recovering from registrar
> I0626 00:04:39.569286 5475 registrar.cpp:313] Recovering registrar
> I0626 00:04:39.600639 5477 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 33.682136ms
> I0626 00:04:39.600661 5477 replica.cpp:320] Persisted replica status to STARTING
> I0626 00:04:39.600790 5476 recover.cpp:451] Replica is in STARTING status
> I0626 00:04:39.601184 5474 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0626 00:04:39.601274 5477 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0626 00:04:39.601465 5471 recover.cpp:542] Updating replica status to VOTING
> I0626 00:04:39.610605 5471 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.076262ms
> I0626 00:04:39.610638 5471 replica.cpp:320] Persisted replica status to VOTING
> I0626 00:04:39.610683 5471 recover.cpp:556] Successfully joined the Paxos group
> I0626 00:04:39.610780 5471 recover.cpp:440] Recover process terminated
> I0626 00:04:39.610946 5474 log.cpp:656] Attempting to start the writer
> I0626 00:04:39.611486 5475 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0626 00:04:39.618924 5475 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 7.418789ms
> I0626 00:04:39.618942 5475 replica.cpp:342] Persisted promised to 1
> I0626 00:04:39.619220 5476 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0626 00:04:39.619763 5476 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0626 00:04:39.627267 5476 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 7.485492ms
> I0626 00:04:39.627295 5476 replica.cpp:676] Persisted action at 0
> I0626 00:04:39.627822 5473 replica.cpp:508] Replica received write request for position 0
> I0626 00:04:39.627861 5473 leveldb.cpp:438] Reading position from leveldb took 17132ns
> I0626 00:04:39.635592 5473 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 7.714322ms
> I0626 00:04:39.635612 5473 replica.cpp:676] Persisted action at 0
> I0626 00:04:39.635797 5473 replica.cpp:655] Replica received learned notice for position 0
> I0626 00:04:39.643941 5473 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 8.129347ms
> I0626 00:04:39.643960 5473 replica.cpp:676] Persisted action at 0
> I0626 00:04:39.643970 5473 replica.cpp:661] Replica learned NOP action at position 0
> I0626 00:04:39.644207 5473 log.cpp:672] Writer started with ending position 0
> I0626 00:04:39.644625 5471 leveldb.cpp:438] Reading position from leveldb took 9128ns
> I0626 00:04:39.646010 5476 registrar.cpp:346] Successfully fetched the registry (0B)
> I0626 00:04:39.646044 5476 registrar.cpp:422] Attempting to update the 'registry'
> I0626 00:04:39.647274 5471 log.cpp:680] Attempting to append 136 bytes to the log
> I0626 00:04:39.647337 5471 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0626 00:04:39.647687 5476 replica.cpp:508] Replica received write request for position 1
> I0626 00:04:39.655206 5476 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 7.499736ms
> I0626 00:04:39.655225 5476 replica.cpp:676] Persisted action at 1
> I0626 00:04:39.655467 5476 replica.cpp:655] Replica received learned notice for position 1
> I0626 00:04:39.663534 5476 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 8.054929ms
> I0626 00:04:39.663554 5476 replica.cpp:676] Persisted action at 1
> I0626 00:04:39.663563 5476 replica.cpp:661] Replica learned APPEND action at position 1
> I0626 00:04:39.663890 5478 registrar.cpp:479] Successfully updated 'registry'
> I0626 00:04:39.663947 5478 registrar.cpp:372] Successfully recovered registrar
> I0626 00:04:39.663969 5476 log.cpp:699] Attempting to truncate the log to 1
> I0626 00:04:39.664044 5478 master.cpp:980] Recovered 0 slaves from the Registry (98B) ; allowing 10mins for slaves to re-register
> I0626 00:04:39.664057 5476 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0626 00:04:39.664341 5476 replica.cpp:508] Replica received write request for position 2
> I0626 00:04:39.664681 5450 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0626 00:04:39.666721 5471 slave.cpp:168] Slave started on 173)@67.195.138.61:55423
> I0626 00:04:39.666741 5471 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/credential'
> I0626 00:04:39.666806 5471 slave.cpp:268] Slave using credential for: test-principal
> I0626 00:04:39.666936 5471 slave.cpp:281] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0626 00:04:39.667000 5471 slave.cpp:326] Slave hostname: juno.apache.org
> I0626 00:04:39.667009 5471 slave.cpp:327] Slave checkpoint: true
> I0626 00:04:39.667572 5478 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta'
> I0626 00:04:39.667703 5475 status_update_manager.cpp:193] Recovering status update manager
> I0626 00:04:39.667840 5475 containerizer.cpp:287] Recovering containerizer
> I0626 00:04:39.668478 5471 slave.cpp:3128] Finished recovery
> I0626 00:04:39.668712 5471 slave.cpp:601] New master detected at master@67.195.138.61:55423
> I0626 00:04:39.668738 5471 slave.cpp:677] Authenticating with master master@67.195.138.61:55423
> I0626 00:04:39.668802 5471 slave.cpp:650] Detecting new master
> I0626 00:04:39.668861 5471 status_update_manager.cpp:167] New master detected at master@67.195.138.61:55423
> I0626 00:04:39.668916 5471 authenticatee.hpp:128] Creating new client SASL connection
> I0626 00:04:39.669087 5471 master.cpp:3499] Authenticating slave(173)@67.195.138.61:55423
> I0626 00:04:39.669203 5471 authenticator.hpp:156] Creating new server SASL connection
> I0626 00:04:39.669340 5471 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0626 00:04:39.669359 5471 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0626 00:04:39.669386 5471 authenticator.hpp:262] Received SASL authentication start
> I0626 00:04:39.669414 5471 authenticator.hpp:384] Authentication requires more steps
> I0626 00:04:39.669457 5471 authenticatee.hpp:265] Received SASL authentication step
> I0626 00:04:39.669514 5471 authenticator.hpp:290] Received SASL authentication step
> I0626 00:04:39.669534 5471 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0626 00:04:39.669543 5471 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0626 00:04:39.669567 5471 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0626 00:04:39.669580 5471 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0626 00:04:39.669589 5471 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:39.669594 5471 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:39.669606 5471 authenticator.hpp:376] Authentication success
> I0626 00:04:39.669641 5471 authenticatee.hpp:305] Authentication success
> I0626 00:04:39.669669 5471 master.cpp:3539] Successfully authenticated principal 'test-principal' at slave(173)@67.195.138.61:55423
> I0626 00:04:39.669761 5450 sched.cpp:139] Version: 0.20.0
> I0626 00:04:39.669764 5478 slave.cpp:734] Successfully authenticated with master master@67.195.138.61:55423
> I0626 00:04:39.669826 5478 slave.cpp:972] Will retry registration in 3.190666ms if necessary
> I0626 00:04:39.669950 5471 master.cpp:2781] Registering slave at slave(173)@67.195.138.61:55423 (juno.apache.org) with id 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:39.669960 5475 sched.cpp:235] New master detected at master@67.195.138.61:55423
> I0626 00:04:39.669977 5475 sched.cpp:285] Authenticating with master master@67.195.138.61:55423
> I0626 00:04:39.670073 5471 registrar.cpp:422] Attempting to update the 'registry'
> I0626 00:04:39.670114 5475 authenticatee.hpp:128] Creating new client SASL connection
> I0626 00:04:39.670263 5475 master.cpp:3499] Authenticating scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423
> I0626 00:04:39.670361 5474 authenticator.hpp:156] Creating new server SASL connection
> I0626 00:04:39.670506 5475 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0626 00:04:39.670526 5475 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0626 00:04:39.670559 5475 authenticator.hpp:262] Received SASL authentication start
> I0626 00:04:39.670590 5475 authenticator.hpp:384] Authentication requires more steps
> I0626 00:04:39.670619 5475 authenticatee.hpp:265] Received SASL authentication step
> I0626 00:04:39.670650 5475 authenticator.hpp:290] Received SASL authentication step
> I0626 00:04:39.670670 5475 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0626 00:04:39.670677 5475 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0626 00:04:39.670687 5475 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0626 00:04:39.670697 5475 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0626 00:04:39.670706 5475 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:39.670712 5475 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:39.670723 5475 authenticator.hpp:376] Authentication success
> I0626 00:04:39.670749 5475 authenticatee.hpp:305] Authentication success
> I0626 00:04:39.670773 5475 master.cpp:3539] Successfully authenticated principal 'test-principal' at scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423
> I0626 00:04:39.670845 5475 sched.cpp:359] Successfully authenticated with master master@67.195.138.61:55423
> I0626 00:04:39.670858 5475 sched.cpp:478] Sending registration request to master@67.195.138.61:55423
> I0626 00:04:39.670899 5475 master.cpp:1241] Received registration request from scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423
> I0626 00:04:39.670922 5475 master.cpp:1201] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0626 00:04:39.671052 5475 master.cpp:1300] Registering framework 20140626-000439-1032504131-55423-5450-0000 at scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423
> I0626 00:04:39.671159 5474 sched.cpp:409] Framework registered with 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.671185 5474 sched.cpp:423] Scheduler::registered took 10223ns
> I0626 00:04:39.671226 5474 hierarchical_allocator_process.hpp:331] Added framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.671241 5474 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0626 00:04:39.671247 5474 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 8574ns
> I0626 00:04:39.671879 5476 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.48781ms
> I0626 00:04:39.671900 5476 replica.cpp:676] Persisted action at 2
> I0626 00:04:39.672164 5471 replica.cpp:655] Replica received learned notice for position 2
> I0626 00:04:39.674092 5472 slave.cpp:972] Will retry registration in 25.467893ms if necessary
> I0626 00:04:39.674108 5476 master.cpp:2769] Ignoring register slave message from slave(173)@67.195.138.61:55423 (juno.apache.org) as admission is already in progress
> I0626 00:04:39.680193 5471 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 8.01285ms
> I0626 00:04:39.680223 5471 leveldb.cpp:401] Deleting ~1 keys from leveldb took 11393ns
> I0626 00:04:39.680234 5471 replica.cpp:676] Persisted action at 2
> I0626 00:04:39.680245 5471 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0626 00:04:39.680585 5472 log.cpp:680] Attempting to append 326 bytes to the log
> I0626 00:04:39.680670 5477 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0626 00:04:39.680953 5474 replica.cpp:508] Replica received write request for position 3
> I0626 00:04:39.688521 5474 leveldb.cpp:343] Persisting action (345 bytes) to leveldb took 7.548316ms
> I0626 00:04:39.688542 5474 replica.cpp:676] Persisted action at 3
> I0626 00:04:39.688750 5474 replica.cpp:655] Replica received learned notice for position 3
> I0626 00:04:39.696851 5474 leveldb.cpp:343] Persisting action (347 bytes) to leveldb took 8.088289ms
> I0626 00:04:39.696869 5474 replica.cpp:676] Persisted action at 3
> I0626 00:04:39.696878 5474 replica.cpp:661] Replica learned APPEND action at position 3
> I0626 00:04:39.697268 5474 registrar.cpp:479] Successfully updated 'registry'
> I0626 00:04:39.697350 5474 log.cpp:699] Attempting to truncate the log to 3
> I0626 00:04:39.697412 5474 master.cpp:2821] Registered slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:39.697423 5474 master.cpp:3967] Adding slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0626 00:04:39.697535 5474 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0626 00:04:39.697618 5474 slave.cpp:768] Registered with master master@67.195.138.61:55423; given slave ID 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:39.697754 5474 slave.cpp:781] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/slave.info'
> I0626 00:04:39.697762 5471 hierarchical_allocator_process.hpp:444] Added slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0626 00:04:39.697845 5471 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 to framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.697854 5474 slave.cpp:2325] Received ping from slave-observer(142)@67.195.138.61:55423
> I0626 00:04:39.698040 5471 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140626-000439-1032504131-55423-5450-0 in 231333ns
> I0626 00:04:39.698051 5474 replica.cpp:508] Replica received write request for position 4
> I0626 00:04:39.698118 5471 master.hpp:794] Adding offer 20140626-000439-1032504131-55423-5450-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:39.698170 5471 master.cpp:3446] Sending 1 offers to framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.698318 5471 sched.cpp:546] Scheduler::resourceOffers took 24371ns
> I0626 00:04:39.699718 5477 master.hpp:804] Removing offer 20140626-000439-1032504131-55423-5450-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:39.699787 5477 master.cpp:2125] Processing reply for offers: [ 20140626-000439-1032504131-55423-5450-0 ] on slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org) for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.699812 5477 master.cpp:2211] Authorizing framework principal 'test-principal' to launch task 897522cc-4ec5-4904-aed0-00b6b8c41028 as user 'jenkins'
> I0626 00:04:39.700160 5477 master.hpp:766] Adding task 897522cc-4ec5-4904-aed0-00b6b8c41028 with resources cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:39.700188 5477 master.cpp:2277] Launching task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 with resources cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:39.700392 5471 slave.cpp:1003] Got assigned task 897522cc-4ec5-4904-aed0-00b6b8c41028 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.700479 5477 hierarchical_allocator_process.hpp:546] Framework 20140626-000439-1032504131-55423-5450-0000 left cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] unused on slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:39.700505 5471 slave.cpp:3400] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/framework.info'
> I0626 00:04:39.700597 5477 hierarchical_allocator_process.hpp:588] Framework 20140626-000439-1032504131-55423-5450-0000 filtered slave 20140626-000439-1032504131-55423-5450-0 for 5secs
> I0626 00:04:39.700686 5471 slave.cpp:3407] Checkpointing framework pid 'scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/framework.pid'
> I0626 00:04:39.700960 5471 slave.cpp:1113] Launching task 897522cc-4ec5-4904-aed0-00b6b8c41028 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.702287 5471 slave.cpp:3722] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/executor.info'
> I0626 00:04:39.702738 5471 slave.cpp:3837] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c/tasks/897522cc-4ec5-4904-aed0-00b6b8c41028/task.info'
> I0626 00:04:39.702744 5476 containerizer.cpp:427] Starting container '9ad3a5ac-3587-47df-96c2-df76ea09328c' for executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework '20140626-000439-1032504131-55423-5450-0000'
> I0626 00:04:39.702987 5471 slave.cpp:1223] Queuing task '897522cc-4ec5-4904-aed0-00b6b8c41028' for executor 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework '20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:39.703039 5471 slave.cpp:562] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c'
> I0626 00:04:39.704654 5477 launcher.cpp:137] Forked child with pid '7596' for container '9ad3a5ac-3587-47df-96c2-df76ea09328c'
> I0626 00:04:39.704891 5477 containerizer.cpp:705] Checkpointing executor's forked pid 7596 to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c/pids/forked.pid'
> I0626 00:04:39.705301 5474 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.183865ms
> I0626 00:04:39.705343 5474 replica.cpp:676] Persisted action at 4
> I0626 00:04:39.705912 5476 containerizer.cpp:537] Fetching URIs for container '9ad3a5ac-3587-47df-96c2-df76ea09328c' using command '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I0626 00:04:39.706073 5471 replica.cpp:655] Replica received learned notice for position 4
> I0626 00:04:39.713664 5471 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 6.238172ms
> I0626 00:04:39.713762 5471 leveldb.cpp:401] Deleting ~2 keys from leveldb took 42244ns
> I0626 00:04:39.713788 5471 replica.cpp:676] Persisted action at 4
> I0626 00:04:39.713810 5471 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0626 00:04:40.378677 5475 slave.cpp:2470] Monitoring executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework '20140626-000439-1032504131-55423-5450-0000' in container '9ad3a5ac-3587-47df-96c2-df76ea09328c'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0626 00:04:40.413177 7631 process.cpp:1671] libprocess is initialized on 67.195.138.61:40619 for 8 cpus
> I0626 00:04:40.414454 7631 exec.cpp:131] Version: 0.20.0
> I0626 00:04:40.415856 7649 exec.cpp:181] Executor started at: executor(1)@67.195.138.61:40619 with pid 7631
> I0626 00:04:40.416453 5471 slave.cpp:1734] Got registration for executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.416527 5471 slave.cpp:1819] Checkpointing executor pid 'executor(1)@67.195.138.61:40619' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c/pids/libprocess.pid'
> I0626 00:04:40.416998 5471 slave.cpp:1853] Flushing queued task 897522cc-4ec5-4904-aed0-00b6b8c41028 for executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.417186 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:40.417322 7648 exec.cpp:205] Executor registered on slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:40.417368 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:40.418385 7648 exec.cpp:217] Executor::registered took 115121ns
> Registered executor on juno.apache.org
> I0626 00:04:40.418544 7648 exec.cpp:292] Executor asked to run task '897522cc-4ec5-4904-aed0-00b6b8c41028'
> Starting task 897522cc-4ec5-4904-aed0-00b6b8c41028
> I0626 00:04:40.418609 7648 exec.cpp:301] Executor::launchTask took 35936ns
> Forked command at 7654
> sh -c 'sleep 1000'
> I0626 00:04:40.420611 7650 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.420953 5473 slave.cpp:2088] Handling status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 from executor(1)@67.195.138.61:40619
> I0626 00:04:40.421188 5474 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.421206 5474 status_update_manager.cpp:499] Creating StatusUpdate stream for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.421469 5474 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.525890 5474 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to master@67.195.138.61:55423
> I0626 00:04:40.526053 5474 master.cpp:3107] Status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 from slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:40.526087 5474 slave.cpp:2246] Status update manager successfully handled status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.526100 5474 slave.cpp:2252] Sending acknowledgement for status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to executor(1)@67.195.138.61:40619
> I0626 00:04:40.526252 5474 sched.cpp:637] Scheduler::statusUpdate took 17393ns
> I0626 00:04:40.526294 5474 master.cpp:2631] Forwarding status update acknowledgement 6d952e6d-b7d7-4f40-9f44-f7c3f81757af for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:40.526371 5474 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.526384 5474 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.526468 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:40.526574 7651 exec.cpp:338] Executor received status update acknowledgement 6d952e6d-b7d7-4f40-9f44-f7c3f81757af for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.526679 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:40.569715 5473 hierarchical_allocator_process.hpp:833] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.569749 5473 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 105698ns
> I0626 00:04:40.576212 5477 slave.cpp:1674] Status update manager successfully handled status update acknowledgement (UUID: 6d952e6d-b7d7-4f40-9f44-f7c3f81757af) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.578642 5450 sched.cpp:139] Version: 0.20.0
> I0626 00:04:40.578886 5475 sched.cpp:235] New master detected at master@67.195.138.61:55423
> I0626 00:04:40.578902 5475 sched.cpp:285] Authenticating with master master@67.195.138.61:55423
> I0626 00:04:40.579040 5475 authenticatee.hpp:128] Creating new client SASL connection
> I0626 00:04:40.579202 5475 master.cpp:3499] Authenticating scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423
> I0626 00:04:40.579313 5475 authenticator.hpp:156] Creating new server SASL connection
> I0626 00:04:40.579414 5475 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0626 00:04:40.579430 5475 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0626 00:04:40.579457 5475 authenticator.hpp:262] Received SASL authentication start
> I0626 00:04:40.579488 5475 authenticator.hpp:384] Authentication requires more steps
> I0626 00:04:40.579514 5475 authenticatee.hpp:265] Received SASL authentication step
> I0626 00:04:40.579551 5475 authenticator.hpp:290] Received SASL authentication step
> I0626 00:04:40.579573 5475 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0626 00:04:40.579586 5475 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0626 00:04:40.579601 5475 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0626 00:04:40.579612 5475 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0626 00:04:40.579619 5475 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:40.579624 5475 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:40.579638 5475 authenticator.hpp:376] Authentication success
> I0626 00:04:40.579664 5475 authenticatee.hpp:305] Authentication success
> I0626 00:04:40.579687 5475 master.cpp:3539] Successfully authenticated principal 'test-principal' at scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423
> I0626 00:04:40.579768 5475 sched.cpp:359] Successfully authenticated with master master@67.195.138.61:55423
> I0626 00:04:40.579781 5475 sched.cpp:478] Sending registration request to master@67.195.138.61:55423
> I0626 00:04:40.579825 5475 master.cpp:1241] Received registration request from scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423
> I0626 00:04:40.579845 5475 master.cpp:1201] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0626 00:04:40.579984 5475 master.cpp:1300] Registering framework 20140626-000439-1032504131-55423-5450-0001 at scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423
> I0626 00:04:40.580056 5475 sched.cpp:409] Framework registered with 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.580075 5475 sched.cpp:423] Scheduler::registered took 8994ns
> I0626 00:04:40.580117 5475 hierarchical_allocator_process.hpp:331] Added framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.580173 5475 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 to framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.580366 5475 hierarchical_allocator_process.hpp:833] Filtered on slave 20140626-000439-1032504131-55423-5450-0 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:40.580378 5475 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 251520ns
> I0626 00:04:40.580454 5475 master.hpp:794] Adding offer 20140626-000439-1032504131-55423-5450-1 with resources cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:40.580509 5475 master.cpp:3446] Sending 1 offers to framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.580796 5476 sched.cpp:546] Scheduler::resourceOffers took 36436ns
> I0626 00:04:40.582280 5476 master.hpp:804] Removing offer 20140626-000439-1032504131-55423-5450-1 with resources cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:40.582362 5476 master.cpp:2125] Processing reply for offers: [ 20140626-000439-1032504131-55423-5450-1 ] on slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org) for framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.582402 5476 master.cpp:2211] Authorizing framework principal 'test-principal' to launch task b1f40647-a2ff-475d-a56b-d2a5db9c1229 as user 'jenkins'
> I0626 00:04:40.582823 5475 master.hpp:766] Adding task b1f40647-a2ff-475d-a56b-d2a5db9c1229 with resources cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:40.582892 5475 master.cpp:2277] Launching task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 with resources cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:40.583001 5474 slave.cpp:1003] Got assigned task b1f40647-a2ff-475d-a56b-d2a5db9c1229 for framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.583097 5474 slave.cpp:3400] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/framework.info'
> I0626 00:04:40.583204 5474 slave.cpp:3407] Checkpointing framework pid 'scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/framework.pid'
> I0626 00:04:40.583442 5474 slave.cpp:1113] Launching task b1f40647-a2ff-475d-a56b-d2a5db9c1229 for framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.584455 5474 slave.cpp:3722] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/executor.info'
> I0626 00:04:40.584846 5474 slave.cpp:3837] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3/tasks/b1f40647-a2ff-475d-a56b-d2a5db9c1229/task.info'
> I0626 00:04:40.584866 5476 containerizer.cpp:427] Starting container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' for executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework '20140626-000439-1032504131-55423-5450-0001'
> I0626 00:04:40.584976 5474 slave.cpp:1223] Queuing task 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' for executor b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework '20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:40.585026 5474 slave.cpp:562] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3'
> I0626 00:04:40.586937 5476 launcher.cpp:137] Forked child with pid '7656' for container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3'
> I0626 00:04:40.587131 5476 containerizer.cpp:705] Checkpointing executor's forked pid 7656 to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3/pids/forked.pid'
> I0626 00:04:40.587872 5477 containerizer.cpp:537] Fetching URIs for container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' using command '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher'
> I0626 00:04:41.384660 5472 slave.cpp:2470] Monitoring executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework '20140626-000439-1032504131-55423-5450-0001' in container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0626 00:04:41.417649 7691 process.cpp:1671] libprocess is initialized on 67.195.138.61:40524 for 8 cpus
> I0626 00:04:41.418674 7691 exec.cpp:131] Version: 0.20.0
> I0626 00:04:41.420272 7712 exec.cpp:181] Executor started at: executor(1)@67.195.138.61:40524 with pid 7691
> I0626 00:04:41.420771 5477 slave.cpp:1734] Got registration for executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.420871 5477 slave.cpp:1819] Checkpointing executor pid 'executor(1)@67.195.138.61:40524' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3/pids/libprocess.pid'
> I0626 00:04:41.421335 5477 slave.cpp:1853] Flushing queued task b1f40647-a2ff-475d-a56b-d2a5db9c1229 for executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.421401 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.421506 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.421622 7709 exec.cpp:205] Executor registered on slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:41.421701 7713 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.421891 7713 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.422695 7709 exec.cpp:217] Executor::registered took 116729ns
> Registered executor on juno.apache.org
> I0626 00:04:41.422817 7709 exec.cpp:292] Executor asked to run task 'b1f40647-a2ff-475d-a56b-d2a5db9c1229'
> Starting task b1f40647-a2ff-475d-a56b-d2a5db9c1229
> I0626 00:04:41.422878 7709 exec.cpp:301] Executor::launchTask took 44617ns
> Forked command at 7714
> sh -c 'sleep 1000'
> I0626 00:04:41.424744 7710 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.425102 5473 slave.cpp:2088] Handling status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 from executor(1)@67.195.138.61:40524
> I0626 00:04:41.425271 5472 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.425309 5472 status_update_manager.cpp:499] Creating StatusUpdate stream for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.425585 5472 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.517669 5472 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 to master@67.195.138.61:55423
> I0626 00:04:41.517848 5474 slave.cpp:2246] Status update manager successfully handled status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.517870 5474 slave.cpp:2252] Sending acknowledgement for status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 to executor(1)@67.195.138.61:40524
> I0626 00:04:41.517985 5471 master.cpp:3107] Status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 from slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:41.518061 5473 sched.cpp:637] Scheduler::statusUpdate took 30727ns
> I0626 00:04:41.518087 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.518188 5473 master.cpp:2631] Forwarding status update acknowledgement 7994ad88-77f5-45a5-91bf-b1f4957fba87 for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 to slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:41.518209 7705 exec.cpp:338] Executor received status update acknowledgement 7994ad88-77f5-45a5-91bf-b1f4957fba87 for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.518237 7713 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.518332 5477 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.518358 5477 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.565961 5477 slave.cpp:1674] Status update manager successfully handled status update acknowledgement (UUID: 7994ad88-77f5-45a5-91bf-b1f4957fba87) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.566172 5450 slave.cpp:486] Slave terminating
> I0626 00:04:41.566315 5476 master.cpp:760] Slave 20140626-000439-1032504131-55423-5450-0 at slave(173)@67.195.138.61:55423 (juno.apache.org) disconnected
> I0626 00:04:41.566337 5476 master.cpp:1602] Disconnecting slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:41.566411 5473 hierarchical_allocator_process.hpp:483] Slave 20140626-000439-1032504131-55423-5450-0 disconnected
> I0626 00:04:41.567461 5450 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
> I0626 00:04:41.569854 5477 slave.cpp:168] Slave started on 174)@67.195.138.61:55423
> I0626 00:04:41.569874 5477 credentials.hpp:35] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/credential'
> I0626 00:04:41.569941 5477 slave.cpp:268] Slave using credential for: test-principal
> I0626 00:04:41.570065 5477 slave.cpp:281] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0626 00:04:41.570139 5477 slave.cpp:326] Slave hostname: juno.apache.org
> I0626 00:04:41.570148 5477 slave.cpp:327] Slave checkpoint: true
> I0626 00:04:41.570361 5478 hierarchical_allocator_process.hpp:833] Filtered on slave 20140626-000439-1032504131-55423-5450-0 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.570382 5478 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 97062ns
> I0626 00:04:41.570710 5476 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta'
> I0626 00:04:41.572727 5475 slave.cpp:3196] Recovering framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.572752 5475 slave.cpp:3572] Recovering executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.572877 5475 slave.cpp:3196] Recovering framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.572904 5475 slave.cpp:3572] Recovering executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.573421 5478 status_update_manager.cpp:193] Recovering status update manager
> I0626 00:04:41.573436 5478 status_update_manager.cpp:201] Recovering executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.573470 5478 status_update_manager.cpp:499] Creating StatusUpdate stream for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.573627 5478 status_update_manager.hpp:306] Replaying status update stream for task b1f40647-a2ff-475d-a56b-d2a5db9c1229
> I0626 00:04:41.573662 5478 status_update_manager.cpp:201] Recovering executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.573689 5478 status_update_manager.cpp:499] Creating StatusUpdate stream for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.573804 5478 status_update_manager.hpp:306] Replaying status update stream for task 897522cc-4ec5-4904-aed0-00b6b8c41028
> I0626 00:04:41.573848 5475 slave.cpp:562] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3'
> I0626 00:04:41.573881 5475 slave.cpp:562] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c'
> I0626 00:04:41.574369 5477 containerizer.cpp:287] Recovering containerizer
> I0626 00:04:41.574404 5477 containerizer.cpp:329] Recovering container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' for executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.574440 5477 containerizer.cpp:329] Recovering container '9ad3a5ac-3587-47df-96c2-df76ea09328c' for executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.575889 5476 slave.cpp:3069] Sending reconnect request to executor 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 at executor(1)@67.195.138.61:40619
> I0626 00:04:41.576014 5476 slave.cpp:3069] Sending reconnect request to executor b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 at executor(1)@67.195.138.61:40524
> I0626 00:04:41.576128 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.576170 7645 exec.cpp:251] Received reconnect request from slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:41.576202 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.576230 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.576308 7705 exec.cpp:251] Received reconnect request from slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:41.576328 7713 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.576519 5472 slave.cpp:1913] Re-registering executor 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.576658 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.576730 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.576750 7650 exec.cpp:228] Executor re-registered on slave 20140626-000439-1032504131-55423-5450-0
> IRe-registered executor on juno.apache.org
> 0626 00:04:41.577729 7650 exec.cpp:240] Executor::reregistered took 50146ns
> I0626 00:04:41.590677 5476 hierarchical_allocator_process.hpp:833] Filtered on slave 20140626-000439-1032504131-55423-5450-0 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.590695 5475 slave.cpp:2037] Cleaning up un-reregistered executors
> I0626 00:04:41.590701 5476 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 56695ns
> I0626 00:04:41.590706 5475 slave.cpp:2055] Killing un-reregistered executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:41.590744 5475 slave.cpp:3128] Finished recovery
> I0626 00:04:41.590900 5474 containerizer.cpp:903] Destroying container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3'
> I0626 00:04:41.592074 5472 slave.cpp:601] New master detected at master@67.195.138.61:55423
> I0626 00:04:41.592099 5472 slave.cpp:677] Authenticating with master master@67.195.138.61:55423
> I0626 00:04:41.592154 5472 slave.cpp:650] Detecting new master
> I0626 00:04:41.592196 5472 status_update_manager.cpp:167] New master detected at master@67.195.138.61:55423
> W0626 00:04:41.592607 5477 slave.cpp:1906] Shutting down executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001 because the slave is not in recovery mode
> I0626 00:04:41.592816 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.592881 7711 exec.cpp:378] Executor asked to shutdown
> I0626 00:04:41.592921 7713 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.592954 7705 exec.cpp:77] Scheduling shutdown of the executor
> IShutting down
> 0626 00:04:41.592994 7711 exec.cpp:393] Executor::shutdown took 49357ns
> Sending SIGTERM to process tree at pid 7714
> I0626 00:04:41.594029 5471 authenticatee.hpp:128] Creating new client SASL connection
> I0626 00:04:41.594419 5472 master.cpp:3499] Authenticating slave(174)@67.195.138.61:55423
> I0626 00:04:41.594646 5476 authenticator.hpp:156] Creating new server SASL connection
> I0626 00:04:41.594898 5476 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0626 00:04:41.594923 5476 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0626 00:04:41.594960 5476 authenticator.hpp:262] Received SASL authentication start
> I0626 00:04:41.595002 5476 authenticator.hpp:384] Authentication requires more steps
> I0626 00:04:41.595039 5476 authenticatee.hpp:265] Received SASL authentication step
> I0626 00:04:41.595095 5476 authenticator.hpp:290] Received SASL authentication step
> I0626 00:04:41.595115 5476 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0626 00:04:41.595124 5476 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0626 00:04:41.595141 5476 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0626 00:04:41.595155 5476 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0626 00:04:41.595162 5476 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:41.595168 5476 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0626 00:04:41.595181 5476 authenticator.hpp:376] Authentication success
> I0626 00:04:41.595219 5476 authenticatee.hpp:305] Authentication success
> I0626 00:04:41.595252 5476 master.cpp:3539] Successfully authenticated principal 'test-principal' at slave(174)@67.195.138.61:55423
> I0626 00:04:41.595978 5471 slave.cpp:734] Successfully authenticated with master master@67.195.138.61:55423
> I0626 00:04:41.596087 5471 slave.cpp:972] Will retry registration in 5.904051ms if necessary
> W0626 00:04:41.596179 5476 master.cpp:2896] Slave at slave(174)@67.195.138.61:55423 (juno.apache.org) is being allowed to re-register with an already in use id (20140626-000439-1032504131-55423-5450-0)
> I0626 00:04:41.596371 5476 slave.cpp:818] Re-registered with master master@67.195.138.61:55423
> I0626 00:04:41.596407 5476 slave.cpp:1584] Updating framework 20140626-000439-1032504131-55423-5450-0000 pid to scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423
> I0626 00:04:41.596454 5476 slave.cpp:1592] Checkpointing framework pid 'scheduler-e66c50d2-2790-4d20-bc77-a57af0e1780b@67.195.138.61:55423' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/framework.pid'
> I0626 00:04:41.596570 5476 slave.cpp:1584] Updating framework 20140626-000439-1032504131-55423-5450-0001 pid to scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423
> I0626 00:04:41.596608 5476 slave.cpp:1592] Checkpointing framework pid 'scheduler-bb54dd52-95dc-4ed9-b69c-7a65f1661180@67.195.138.61:55423' to '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/framework.pid'
> I0626 00:04:41.596710 5476 hierarchical_allocator_process.hpp:497] Slave 20140626-000439-1032504131-55423-5450-0 reconnected
> I0626 00:04:41.597498 5476 master.cpp:2461] Asked to kill task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.597523 5476 master.cpp:2562] Telling slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org) to kill task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.597580 5476 slave.cpp:1279] Asked to kill task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:41.597724 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:41.597790 7645 exec.cpp:312] Executor asked to kill task '897522cc-4ec5-4904-aed0-00b6b8c41028'
> I0626 00:04:41.597796 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:41.597843 7645 exec.cpp:321] Executor::killTask took 26639ns
> Shutting down
> Sending SIGTERM to process tree at pid 7654
> Killing the following process trees:
> [
> -+- 7654 sh -c sleep 1000
> \--- 7655 sleep 1000
> ]
> I0626 00:04:41.656000 5479 process.cpp:1037] Socket closed while receiving
> Command terminated with signal Terminated (pid: 7654)
> I0626 00:04:42.421964 7649 exec.cpp:524] Executor sending status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.422332 5477 slave.cpp:2088] Handling status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 from executor(1)@67.195.138.61:40619
> I0626 00:04:42.422384 5477 slave.cpp:3770] Terminating task 897522cc-4ec5-4904-aed0-00b6b8c41028
> I0626 00:04:42.422912 5472 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.422946 5472 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.558498 5472 status_update_manager.cpp:373] Forwarding status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to master@67.195.138.61:55423
> I0626 00:04:42.558712 5477 slave.cpp:2246] Status update manager successfully handled status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.558743 5477 slave.cpp:2252] Sending acknowledgement for status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to executor(1)@67.195.138.61:40619
> I0626 00:04:42.558749 5476 master.cpp:3107] Status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 from slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:42.558820 5476 master.hpp:784] Removing task 897522cc-4ec5-4904-aed0-00b6b8c41028 with resources cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:42.558917 5478 sched.cpp:637] Scheduler::statusUpdate took 40786ns
> I0626 00:04:42.559017 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:42.559092 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:42.559100 7650 exec.cpp:338] Executor received status update acknowledgement 3bd1b60e-8496-4254-8188-c160b6a7e498 for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.559386 5471 master.cpp:2631] Forwarding status update acknowledgement 3bd1b60e-8496-4254-8188-c160b6a7e498 for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000 to slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:42.559453 5474 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):1; mem(*):512) on slave 20140626-000439-1032504131-55423-5450-0 from framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.559494 5471 master.cpp:2461] Asked to kill task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.559516 5471 master.cpp:2562] Telling slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org) to kill task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.559541 5474 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.559577 5474 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_KILLED (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.559608 5472 slave.cpp:1279] Asked to kill task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> W0626 00:04:42.559625 5472 slave.cpp:1364] Ignoring kill task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 because the executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' is terminating/terminated
> I0626 00:04:42.569269 5476 master.cpp:122] No whitelist given. Advertising offers for all slaves
> I0626 00:04:42.591553 5478 containerizer.cpp:1019] Executor for container '44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' has exited
> I0626 00:04:42.591665 5477 hierarchical_allocator_process.hpp:833] Filtered cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.591794 5477 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 to framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.591970 5477 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 352174ns
> I0626 00:04:42.592067 5471 master.hpp:794] Adding offer 20140626-000439-1032504131-55423-5450-2 with resources cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:42.592103 5471 master.cpp:3446] Sending 1 offers to framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.592118 5473 slave.cpp:2528] Executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001 terminated with signal Killed
> E0626 00:04:42.592233 5477 slave.cpp:2796] Failed to unmonitor container for executor b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001: Not monitored
> I0626 00:04:42.592279 5472 sched.cpp:546] Scheduler::resourceOffers took 32048ns
> I0626 00:04:42.592439 5472 master.hpp:804] Removing offer 20140626-000439-1032504131-55423-5450-2 with resources cpus(*):1; mem(*):512 on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> I0626 00:04:42.592495 5472 master.cpp:2125] Processing reply for offers: [ 20140626-000439-1032504131-55423-5450-2 ] on slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org) for framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.592707 5475 hierarchical_allocator_process.hpp:546] Framework 20140626-000439-1032504131-55423-5450-0001 left cpus(*):1; mem(*):512 unused on slave 20140626-000439-1032504131-55423-5450-0
> I0626 00:04:42.592865 5475 hierarchical_allocator_process.hpp:588] Framework 20140626-000439-1032504131-55423-5450-0001 filtered slave 20140626-000439-1032504131-55423-5450-0 for 5secs
> I0626 00:04:42.593211 5473 slave.cpp:2088] Handling status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 from @0.0.0.0:0
> I0626 00:04:42.593237 5473 slave.cpp:3770] Terminating task b1f40647-a2ff-475d-a56b-d2a5db9c1229
> W0626 00:04:42.593387 5472 containerizer.cpp:809] Ignoring update for unknown container: 44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3
> I0626 00:04:42.600702 5474 status_update_manager.cpp:530] Cleaning up status update stream for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.600874 5473 slave.cpp:1674] Status update manager successfully handled status update acknowledgement (UUID: 3bd1b60e-8496-4254-8188-c160b6a7e498) for task 897522cc-4ec5-4904-aed0-00b6b8c41028 of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.600895 5473 slave.cpp:3812] Completing task 897522cc-4ec5-4904-aed0-00b6b8c41028
> I0626 00:04:42.600913 5474 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.600939 5474 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634199 5474 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 to master@67.195.138.61:55423
> I0626 00:04:42.634354 5475 master.cpp:3107] Status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 from slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:42.634373 5477 slave.cpp:2246] Status update manager successfully handled status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634428 5473 sched.cpp:637] Scheduler::statusUpdate took 22610ns
> I0626 00:04:42.634520 5475 master.hpp:784] Removing task b1f40647-a2ff-475d-a56b-d2a5db9c1229 with resources cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20140626-000439-1032504131-55423-5450-0 (juno.apache.org)
> ../../src/tests/slave_recovery_tests.cpp:2930: Failure
> Value of: status2.get().state()
> Actual: TASK_FAILED
> Expected: TASK_KILLED
> I0626 00:04:42.634699 5475 master.cpp:2631] Forwarding status update acknowledgement 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001 to slave 20140626-000439-1032504131-55423-5450-0 at slave(174)@67.195.138.61:55423 (juno.apache.org)
> I0626 00:04:42.634778 5472 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140626-000439-1032504131-55423-5450-0 from framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634804 5475 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634836 5475 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_FAILED (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634843 5472 master.cpp:710] Framework 20140626-000439-1032504131-55423-5450-0001 disconnected
> I0626 00:04:42.634857 5472 master.cpp:1577] Deactivating framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.634881 5472 master.cpp:732] Giving framework 20140626-000439-1032504131-55423-5450-0001 0ns to failover
> I0626 00:04:42.635025 5472 hierarchical_allocator_process.hpp:407] Deactivated framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635056 5472 master.cpp:3362] Framework failover timeout, removing framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635066 5472 master.cpp:3821] Removing framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635154 5472 master.cpp:710] Framework 20140626-000439-1032504131-55423-5450-0000 disconnected
> I0626 00:04:42.635167 5472 master.cpp:1577] Deactivating framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.635226 5472 master.cpp:732] Giving framework 20140626-000439-1032504131-55423-5450-0000 0ns to failover
> I0626 00:04:42.635254 5478 hierarchical_allocator_process.hpp:362] Removed framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635267 5476 slave.cpp:1407] Asked to shut down framework 20140626-000439-1032504131-55423-5450-0001 by master@67.195.138.61:55423
> I0626 00:04:42.635285 5476 slave.cpp:1432] Shutting down framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635301 5476 slave.cpp:2662] Cleaning up executor 'b1f40647-a2ff-475d-a56b-d2a5db9c1229' of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635308 5478 hierarchical_allocator_process.hpp:407] Deactivated framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.635340 5478 master.cpp:3362] Framework failover timeout, removing framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.635349 5478 master.cpp:3821] Removing framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.635469 5478 hierarchical_allocator_process.hpp:362] Removed framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.635601 5450 master.cpp:619] Master terminating
> I0626 00:04:42.635840 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' for gc 6.99999264157333days in the future
> I0626 00:04:42.635916 5476 slave.cpp:2737] Cleaning up framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.635916 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229' for gc 6.99999264090074days in the future
> I0626 00:04:42.635960 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229/runs/44b9f0a1-fcf4-4b33-b6dc-2d886304e8b3' for gc 6.99999264048593days in the future
> I0626 00:04:42.636015 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001/executors/b1f40647-a2ff-475d-a56b-d2a5db9c1229' for gc 6.99999264009185days in the future
> I0626 00:04:42.636034 5476 slave.cpp:1407] Asked to shut down framework 20140626-000439-1032504131-55423-5450-0000 by master@67.195.138.61:55423
> I0626 00:04:42.636049 5476 slave.cpp:1432] Shutting down framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.636061 5476 slave.cpp:2808] Shutting down executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:42.636064 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001' for gc 6.99999263944593days in the future
> I0626 00:04:42.636107 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0001' for gc 6.9999926390963days in the future
> I0626 00:04:42.636207 5476 slave.cpp:2332] master@67.195.138.61:55423 exited
> W0626 00:04:42.636220 5476 slave.cpp:2335] Master disconnected! Waiting for a new master to be elected
> I0626 00:04:42.636307 5479 process.cpp:1098] Socket closed while receiving
> I0626 00:04:42.636379 7653 process.cpp:1037] Socket closed while receiving
> I0626 00:04:42.636382 7648 exec.cpp:378] Executor asked to shutdown
> I0626 00:04:42.636535 7648 exec.cpp:393] Executor::shutdown took 6684ns
> I0626 00:04:42.636545 7649 exec.cpp:77] Scheduling shutdown of the executor
> I0626 00:04:42.637948 5472 containerizer.cpp:903] Destroying container '9ad3a5ac-3587-47df-96c2-df76ea09328c'
> I0626 00:04:42.672613 5479 process.cpp:1037] Socket closed while receiving
> I0626 00:04:42.692251 5475 status_update_manager.cpp:530] Cleaning up status update stream for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.692435 5475 status_update_manager.cpp:282] Closing status update streams for framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:42.692450 5471 slave.cpp:1674] Status update manager successfully handled status update acknowledgement (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of framework 20140626-000439-1032504131-55423-5450-0001
> E0626 00:04:42.692477 5471 slave.cpp:1685] Status update acknowledgement (UUID: 69181ee5-c620-4d1a-b5d2-d7cd03a0bc7e) for task b1f40647-a2ff-475d-a56b-d2a5db9c1229 of unknown framework 20140626-000439-1032504131-55423-5450-0001
> I0626 00:04:43.592118 5473 containerizer.cpp:1019] Executor for container '9ad3a5ac-3587-47df-96c2-df76ea09328c' has exited
> I0626 00:04:43.592550 5475 slave.cpp:2528] Executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000 terminated with signal Killed
> I0626 00:04:43.592599 5475 slave.cpp:2662] Cleaning up executor '897522cc-4ec5-4904-aed0-00b6b8c41028' of framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:43.592901 5475 slave.cpp:2737] Cleaning up framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:43.592900 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c' for gc 6.99999313928296days in the future
> I0626 00:04:43.592991 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028' for gc 6.99999313866963days in the future
> I0626 00:04:43.592985 5471 status_update_manager.cpp:282] Closing status update streams for framework 20140626-000439-1032504131-55423-5450-0000
> I0626 00:04:43.593022 5475 slave.cpp:486] Slave terminating
> I0626 00:04:43.593040 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028/runs/9ad3a5ac-3587-47df-96c2-df76ea09328c' for gc 6.99999313827556days in the future
> I0626 00:04:43.593086 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000/executors/897522cc-4ec5-4904-aed0-00b6b8c41028' for gc 6.99999313791704days in the future
> I0626 00:04:43.593125 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000' for gc 6.99999313702518days in the future
> I0626 00:04:43.593166 5472 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_MultipleFrameworks_G6ObtK/meta/slaves/20140626-000439-1032504131-55423-5450-0/frameworks/20140626-000439-1032504131-55423-5450-0000' for gc 6.99999313664296days in the future
> [ FAILED ] SlaveRecoveryTest/0.MultipleFrameworks, where TypeParam = mesos::internal::slave::MesosContainerizer (4218 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)