mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Chris Lambert (JIRA)" <j...@apache.org>
Subject [jira] [Assigned] (MESOS-1545) SlaveRecoveryTest/0.MultipleFrameworks is flaky
Date Mon, 30 Jun 2014 18:39:24 GMT

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

Chris Lambert reassigned MESOS-1545:
------------------------------------

    Assignee: Ian Downes

> 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
>            Assignee: Ian Downes
>
> {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.2#6252)

Mime
View raw message