[ https://issues.apache.org/jira/browse/MESOS-1545?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ian Downes updated MESOS-1545: ------------------------------ Assignee: (was: 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 > > {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)