You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Ian Downes (JIRA)" <ji...@apache.org> on 2014/06/17 02:29:04 UTC
[jira] [Commented] (MESOS-1485)
MasterTest.ShutdownFrameworkWhileTaskRunning is flaky.
[ https://issues.apache.org/jira/browse/MESOS-1485?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14033242#comment-14033242 ]
Ian Downes commented on MESOS-1485:
-----------------------------------
Might be due to https://issues.apache.org/jira/browse/MESOS-1438
> MasterTest.ShutdownFrameworkWhileTaskRunning is flaky.
> ------------------------------------------------------
>
> Key: MESOS-1485
> URL: https://issues.apache.org/jira/browse/MESOS-1485
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.20.0
> Reporter: Benjamin Mahler
>
> {noformat}
> [ RUN ] MasterTest.ShutdownFrameworkWhileTaskRunning
> Using temporary directory '/tmp/MasterTest_ShutdownFrameworkWhileTaskRunning_9VQU5Z'
> I0613 13:43:33.627049 20698 leveldb.cpp:176] Opened db in 2.864479ms
> I0613 13:43:33.628389 20698 leveldb.cpp:183] Compacted db in 951098ns
> I0613 13:43:33.628742 20698 leveldb.cpp:198] Created db iterator in 5453ns
> I0613 13:43:33.629006 20698 leveldb.cpp:204] Seeked to beginning of db in 1360ns
> I0613 13:43:33.629263 20698 leveldb.cpp:273] Iterated through 0 keys in the db in 792ns
> I0613 13:43:33.629536 20698 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0613 13:43:33.630028 20718 recover.cpp:425] Starting replica recovery
> I0613 13:43:33.630096 20718 recover.cpp:451] Replica is in EMPTY status
> I0613 13:43:33.630369 20718 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0613 13:43:33.630426 20718 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0613 13:43:33.630522 20718 recover.cpp:542] Updating replica status to STARTING
> I0613 13:43:33.631408 20718 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 830669ns
> I0613 13:43:33.631428 20718 replica.cpp:320] Persisted replica status to STARTING
> I0613 13:43:33.631489 20718 recover.cpp:451] Replica is in STARTING status
> I0613 13:43:33.632063 20725 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0613 13:43:33.632124 20725 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0613 13:43:33.632216 20725 recover.cpp:542] Updating replica status to VOTING
> I0613 13:43:33.633152 20725 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 712321ns
> I0613 13:43:33.633172 20725 replica.cpp:320] Persisted replica status to VOTING
> I0613 13:43:33.633523 20718 recover.cpp:556] Successfully joined the Paxos group
> I0613 13:43:33.633582 20718 recover.cpp:440] Recover process terminated
> I0613 13:43:33.636837 20725 master.cpp:280] Master 20140613-134333-16842879-46436-20698 (saucy) started on 127.0.1.1:46436
> I0613 13:43:33.636860 20725 master.cpp:317] Master only allowing authenticated frameworks to register
> I0613 13:43:33.636867 20725 master.cpp:322] Master only allowing authenticated slaves to register
> I0613 13:43:33.636873 20725 credentials.hpp:35] Loading credentials for authentication from '/tmp/MasterTest_ShutdownFrameworkWhileTaskRunning_9VQU5Z/credentials'
> I0613 13:43:33.636940 20725 master.cpp:348] Authorization enabled
> I0613 13:43:33.637294 20725 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:46436
> I0613 13:43:33.637327 20725 master.cpp:114] No whitelist given. Advertising offers for all slaves
> I0613 13:43:33.637473 20725 master.cpp:961] The newly elected leader is master@127.0.1.1:46436 with id 20140613-134333-16842879-46436-20698
> I0613 13:43:33.637485 20725 master.cpp:974] Elected as the leading master!
> I0613 13:43:33.637490 20725 master.cpp:792] Recovering from registrar
> I0613 13:43:33.637532 20725 registrar.cpp:313] Recovering registrar
> I0613 13:43:33.637709 20725 log.cpp:656] Attempting to start the writer
> I0613 13:43:33.637974 20725 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0613 13:43:33.638885 20725 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 891849ns
> I0613 13:43:33.639226 20725 replica.cpp:342] Persisted promised to 1
> I0613 13:43:33.639634 20725 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0613 13:43:33.640210 20725 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0613 13:43:33.641263 20725 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 760752ns
> I0613 13:43:33.641592 20725 replica.cpp:676] Persisted action at 0
> I0613 13:43:33.642072 20725 replica.cpp:508] Replica received write request for position 0
> I0613 13:43:33.642380 20725 leveldb.cpp:438] Reading position from leveldb took 18023ns
> I0613 13:43:33.643101 20725 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 426221ns
> I0613 13:43:33.643384 20725 replica.cpp:676] Persisted action at 0
> I0613 13:43:33.646813 20721 replica.cpp:655] Replica received learned notice for position 0
> I0613 13:43:33.648020 20721 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.181452ms
> I0613 13:43:33.648048 20721 replica.cpp:676] Persisted action at 0
> I0613 13:43:33.648056 20721 replica.cpp:661] Replica learned NOP action at position 0
> I0613 13:43:33.648200 20721 log.cpp:672] Writer started with ending position 0
> I0613 13:43:33.648403 20721 leveldb.cpp:438] Reading position from leveldb took 10566ns
> I0613 13:43:33.649822 20721 registrar.cpp:346] Successfully fetched the registry (0B)
> I0613 13:43:33.649847 20721 registrar.cpp:422] Attempting to update the 'registry'
> I0613 13:43:33.651159 20720 log.cpp:680] Attempting to append 118 bytes to the log
> I0613 13:43:33.651206 20720 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0613 13:43:33.651371 20720 replica.cpp:508] Replica received write request for position 1
> I0613 13:43:33.652210 20720 leveldb.cpp:343] Persisting action (135 bytes) to leveldb took 819464ns
> I0613 13:43:33.652230 20720 replica.cpp:676] Persisted action at 1
> I0613 13:43:33.652389 20720 replica.cpp:655] Replica received learned notice for position 1
> I0613 13:43:33.652727 20720 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 321817ns
> I0613 13:43:33.652745 20720 replica.cpp:676] Persisted action at 1
> I0613 13:43:33.652751 20720 replica.cpp:661] Replica learned APPEND action at position 1
> I0613 13:43:33.652977 20720 registrar.cpp:479] Successfully updated 'registry'
> I0613 13:43:33.653012 20720 registrar.cpp:372] Successfully recovered registrar
> I0613 13:43:33.653044 20720 log.cpp:699] Attempting to truncate the log to 1
> I0613 13:43:33.653303 20720 master.cpp:819] Recovered 0 slaves from the Registry (82B) ; allowing 10mins for slaves to re-register
> I0613 13:43:33.653589 20720 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0613 13:43:33.653959 20720 replica.cpp:508] Replica received write request for position 2
> I0613 13:43:33.654187 20720 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 205554ns
> I0613 13:43:33.654206 20720 replica.cpp:676] Persisted action at 2
> I0613 13:43:33.654505 20720 replica.cpp:655] Replica received learned notice for position 2
> I0613 13:43:33.654839 20720 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 311783ns
> I0613 13:43:33.654877 20720 leveldb.cpp:401] Deleting ~1 keys from leveldb took 19766ns
> I0613 13:43:33.654888 20720 replica.cpp:676] Persisted action at 2
> I0613 13:43:33.654896 20720 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0613 13:43:33.657698 20725 slave.cpp:143] Slave started on 102)@127.0.1.1:46436
> I0613 13:43:33.657717 20725 credentials.hpp:35] Loading credentials for authentication from '/tmp/MasterTest_ShutdownFrameworkWhileTaskRunning_FC1YqF/credential'
> I0613 13:43:33.657771 20725 slave.cpp:243] Slave using credential for: test-principal
> I0613 13:43:33.657847 20725 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0613 13:43:33.658311 20725 slave.cpp:284] Slave hostname: saucy
> I0613 13:43:33.658327 20725 slave.cpp:285] Slave checkpoint: false
> I0613 13:43:33.658671 20722 state.cpp:33] Recovering state from '/tmp/MasterTest_ShutdownFrameworkWhileTaskRunning_FC1YqF/meta'
> I0613 13:43:33.658967 20722 status_update_manager.cpp:193] Recovering status update manager
> I0613 13:43:33.659046 20722 slave.cpp:3024] Finished recovery
> I0613 13:43:33.659266 20722 slave.cpp:537] New master detected at master@127.0.1.1:46436
> I0613 13:43:33.659291 20722 slave.cpp:613] Authenticating with master master@127.0.1.1:46436
> I0613 13:43:33.659615 20722 slave.cpp:586] Detecting new master
> I0613 13:43:33.659658 20722 status_update_manager.cpp:167] New master detected at master@127.0.1.1:46436
> I0613 13:43:33.659692 20722 authenticatee.hpp:128] Creating new client SASL connection
> I0613 13:43:33.659826 20722 master.cpp:3341] Authenticating slave(102)@127.0.1.1:46436
> I0613 13:43:33.659906 20722 authenticator.hpp:156] Creating new server SASL connection
> I0613 13:43:33.660008 20722 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0613 13:43:33.660027 20722 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0613 13:43:33.660048 20722 authenticator.hpp:262] Received SASL authentication start
> I0613 13:43:33.660084 20722 authenticator.hpp:384] Authentication requires more steps
> I0613 13:43:33.660107 20722 authenticatee.hpp:265] Received SASL authentication step
> I0613 13:43:33.660138 20722 authenticator.hpp:290] Received SASL authentication step
> I0613 13:43:33.660153 20722 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0613 13:43:33.660161 20722 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0613 13:43:33.660169 20722 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0613 13:43:33.660177 20722 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0613 13:43:33.660183 20722 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0613 13:43:33.660187 20722 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0613 13:43:33.660197 20722 authenticator.hpp:376] Authentication success
> I0613 13:43:33.660220 20722 authenticatee.hpp:305] Authentication success
> I0613 13:43:33.660239 20722 master.cpp:3381] Successfully authenticated principal 'test-principal' at slave(102)@127.0.1.1:46436
> I0613 13:43:33.660298 20722 slave.cpp:670] Successfully authenticated with master master@127.0.1.1:46436
> I0613 13:43:33.660332 20722 slave.cpp:908] Will retry registration in 11.032485ms if necessary
> I0613 13:43:33.660684 20724 master.cpp:2620] Registering slave at slave(102)@127.0.1.1:46436 (saucy) with id 20140613-134333-16842879-46436-20698-0
> I0613 13:43:33.660775 20724 registrar.cpp:422] Attempting to update the 'registry'
> I0613 13:43:33.662130 20719 log.cpp:680] Attempting to append 289 bytes to the log
> I0613 13:43:33.662173 20719 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0613 13:43:33.662334 20719 replica.cpp:508] Replica received write request for position 3
> I0613 13:43:33.663225 20719 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 872698ns
> I0613 13:43:33.663244 20719 replica.cpp:676] Persisted action at 3
> I0613 13:43:33.663400 20719 replica.cpp:655] Replica received learned notice for position 3
> I0613 13:43:33.664193 20719 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 775120ns
> I0613 13:43:33.664212 20719 replica.cpp:676] Persisted action at 3
> I0613 13:43:33.664221 20719 replica.cpp:661] Replica learned APPEND action at position 3
> I0613 13:43:33.664463 20719 registrar.cpp:479] Successfully updated 'registry'
> I0613 13:43:33.664523 20719 log.cpp:699] Attempting to truncate the log to 3
> I0613 13:43:33.664567 20719 master.cpp:2660] Registered slave 20140613-134333-16842879-46436-20698-0 at slave(102)@127.0.1.1:46436 (saucy)
> I0613 13:43:33.664580 20719 master.cpp:3763] Adding slave 20140613-134333-16842879-46436-20698-0 at slave(102)@127.0.1.1:46436 (saucy) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0613 13:43:33.664660 20719 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0613 13:43:33.664721 20719 slave.cpp:704] Registered with master master@127.0.1.1:46436; given slave ID 20140613-134333-16842879-46436-20698-0
> I0613 13:43:33.664779 20719 hierarchical_allocator_process.hpp:444] Added slave 20140613-134333-16842879-46436-20698-0 (saucy) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0613 13:43:33.664810 20719 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140613-134333-16842879-46436-20698-0 in 6017ns
> I0613 13:43:33.664942 20719 replica.cpp:508] Replica received write request for position 4
> I0613 13:43:33.665277 20719 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 317631ns
> I0613 13:43:33.665295 20719 replica.cpp:676] Persisted action at 4
> I0613 13:43:33.665447 20719 replica.cpp:655] Replica received learned notice for position 4
> I0613 13:43:33.665771 20719 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 306138ns
> I0613 13:43:33.666055 20719 leveldb.cpp:401] Deleting ~2 keys from leveldb took 38055ns
> I0613 13:43:33.666390 20719 replica.cpp:676] Persisted action at 4
> I0613 13:43:33.666651 20719 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0613 13:43:33.668051 20698 sched.cpp:128] Version: 0.20.0
> I0613 13:43:33.668491 20718 sched.cpp:224] New master detected at master@127.0.1.1:46436
> I0613 13:43:33.668514 20718 sched.cpp:274] Authenticating with master master@127.0.1.1:46436
> I0613 13:43:33.668580 20718 authenticatee.hpp:128] Creating new client SASL connection
> I0613 13:43:33.668704 20718 master.cpp:3341] Authenticating scheduler(85)@127.0.1.1:46436
> I0613 13:43:33.668774 20718 authenticator.hpp:156] Creating new server SASL connection
> I0613 13:43:33.669139 20718 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0613 13:43:33.669158 20718 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0613 13:43:33.669180 20718 authenticator.hpp:262] Received SASL authentication start
> I0613 13:43:33.669211 20718 authenticator.hpp:384] Authentication requires more steps
> I0613 13:43:33.669234 20718 authenticatee.hpp:265] Received SASL authentication step
> I0613 13:43:33.669262 20718 authenticator.hpp:290] Received SASL authentication step
> I0613 13:43:33.669275 20718 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0613 13:43:33.669281 20718 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0613 13:43:33.669288 20718 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0613 13:43:33.669296 20718 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0613 13:43:33.669302 20718 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0613 13:43:33.669306 20718 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0613 13:43:33.669316 20718 authenticator.hpp:376] Authentication success
> I0613 13:43:33.669337 20718 authenticatee.hpp:305] Authentication success
> I0613 13:43:33.669355 20718 master.cpp:3381] Successfully authenticated principal 'test-principal' at scheduler(85)@127.0.1.1:46436
> I0613 13:43:33.669411 20718 sched.cpp:348] Successfully authenticated with master master@127.0.1.1:46436
> I0613 13:43:33.669425 20718 sched.cpp:467] Sending registration request to master@127.0.1.1:46436
> I0613 13:43:33.669461 20718 master.cpp:1080] Received registration request from scheduler(85)@127.0.1.1:46436
> I0613 13:43:33.669477 20718 master.cpp:1040] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0613 13:43:33.669560 20718 master.cpp:1139] Registering framework 20140613-134333-16842879-46436-20698-0000 at scheduler(85)@127.0.1.1:46436
> I0613 13:43:33.669615 20718 sched.cpp:398] Framework registered with 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.669634 20718 sched.cpp:412] Scheduler::registered took 8318ns
> I0613 13:43:33.669661 20718 hierarchical_allocator_process.hpp:331] Added framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.669692 20718 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 to framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.669774 20718 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 102544ns
> I0613 13:43:33.669821 20718 master.hpp:720] Adding offer 20140613-134333-16842879-46436-20698-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 (saucy)
> I0613 13:43:33.669859 20718 master.cpp:3288] Sending 1 offers to framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.669947 20718 sched.cpp:535] Scheduler::resourceOffers took 14506ns
> I0613 13:43:33.670584 20721 master.hpp:730] Removing offer 20140613-134333-16842879-46436-20698-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 (saucy)
> I0613 13:43:33.670639 20721 master.cpp:1964] Processing reply for offers: [ 20140613-134333-16842879-46436-20698-0 ] on slave 20140613-134333-16842879-46436-20698-0 at slave(102)@127.0.1.1:46436 (saucy) for framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.670665 20721 master.cpp:2050] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
> I0613 13:43:33.671188 20721 master.hpp:692] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 (saucy)
> I0613 13:43:33.671231 20721 master.cpp:2116] Launching task 1 of framework 20140613-134333-16842879-46436-20698-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 at slave(102)@127.0.1.1:46436 (saucy)
> I0613 13:43:33.671710 20721 slave.cpp:939] Got assigned task 1 for framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.671861 20721 slave.cpp:1049] Launching task 1 for framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.674471 20721 exec.cpp:131] Version: 0.20.0
> I0613 13:43:33.674888 20722 exec.cpp:181] Executor started at: executor(29)@127.0.1.1:46436 with pid 20698
> I0613 13:43:33.675216 20721 slave.cpp:1159] Queuing task '1' for executor default of framework '20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.675590 20721 slave.cpp:498] Successfully attached file '/tmp/MasterTest_ShutdownFrameworkWhileTaskRunning_FC1YqF/slaves/20140613-134333-16842879-46436-20698-0/frameworks/20140613-134333-16842879-46436-20698-0000/executors/default/runs/a1869a2a-fe8b-477f-970d-6e53feb40a50'
> I0613 13:43:33.675885 20721 slave.cpp:1670] Got registration for executor 'default' of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.676293 20720 exec.cpp:205] Executor registered on slave 20140613-134333-16842879-46436-20698-0
> I0613 13:43:33.677309 20720 exec.cpp:217] Executor::registered took 15422ns
> I0613 13:43:33.677489 20721 slave.cpp:1789] Flushing queued task 1 for executor 'default' of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.677862 20722 exec.cpp:292] Executor asked to run task '1'
> I0613 13:43:33.677898 20722 exec.cpp:301] Executor::launchTask took 18908ns
> I0613 13:43:33.679055 20722 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.679344 20721 slave.cpp:2361] Monitoring executor 'default' of framework '20140613-134333-16842879-46436-20698-0000' in container 'a1869a2a-fe8b-477f-970d-6e53feb40a50'
> I0613 13:43:33.679779 20721 slave.cpp:2024] Handling status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000 from executor(29)@127.0.1.1:46436
> I0613 13:43:33.680143 20725 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.680162 20725 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.680205 20725 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000 to master@127.0.1.1:46436
> I0613 13:43:33.680414 20725 master.cpp:2946] Status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000 from slave 20140613-134333-16842879-46436-20698-0 at slave(102)@127.0.1.1:46436 (saucy)
> I0613 13:43:33.680483 20725 sched.cpp:626] Scheduler::statusUpdate took 14951ns
> I0613 13:43:33.680819 20720 sched.cpp:731] Stopping framework '20140613-134333-16842879-46436-20698-0000'
> I0613 13:43:33.680887 20723 master.cpp:1369] Asked to unregister framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.680899 20723 master.cpp:3632] Removing framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.680951 20723 master.hpp:710] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140613-134333-16842879-46436-20698-0 (saucy)
> W0613 13:43:33.681009 20723 master.cpp:4049] Removing task 1 of framework 20140613-134333-16842879-46436-20698-0000 and slave 20140613-134333-16842879-46436-20698-0 in non-terminal state TASK_RUNNING
> I0613 13:43:33.681057 20723 hierarchical_allocator_process.hpp:407] Deactivated framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.681121 20723 hierarchical_allocator_process.hpp:635] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140613-134333-16842879-46436-20698-0 from framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.681164 20723 hierarchical_allocator_process.hpp:362] Removed framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.681426 20723 master.cpp:575] Master terminating
> I0613 13:43:33.687536 20725 status_update_manager.cpp:398] Received status update acknowledgement (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.687815 20721 slave.cpp:1343] Asked to shut down framework 20140613-134333-16842879-46436-20698-0000 by master@127.0.1.1:46436
> I0613 13:43:33.691007 20721 slave.cpp:1368] Shutting down framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.691293 20721 slave.cpp:2704] Shutting down executor 'default' of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.695140 20721 slave.cpp:2230] master@127.0.1.1:46436 exited
> W0613 13:43:33.695545 20721 slave.cpp:2233] Master disconnected! Waiting for a new master to be elected
> I0613 13:43:33.696112 20721 slave.cpp:2145] Status update manager successfully handled status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.696370 20721 slave.cpp:2151] Sending acknowledgement for status update TASK_RUNNING (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000 to executor(29)@127.0.1.1:46436
> I0613 13:43:33.696689 20721 slave.cpp:1610] Status update manager successfully handled status update acknowledgement (UUID: b1962a8c-596f-4987-acc6-62cc5fce0486) for task 1 of framework 20140613-134333-16842879-46436-20698-0000
> I0613 13:43:33.696981 20721 slave.cpp:2774] Killing executor 'default' of framework 20140613-134333-16842879-46436-20698-0000
> F0613 13:43:33.697331 20721 containerizer.cpp:194] Check failed: drivers.contains(containerId) Failed to terminate container a1869a2a-fe8b-477f-970d-6e53feb40a50 because it is has not been started
> *** Check failure stack trace: ***
> I0613 13:43:33.696081 20698 exec.cpp:378] Executor asked to shutdown
> I0613 13:43:33.703697 20698 exec.cpp:393] Executor::shutdown took 29869ns
> @ 0x2b232dc92bad google::LogMessage::Fail()
> @ 0x2b232dc949ed google::LogMessage::SendToLog()
> @ 0x2b232dc9279c google::LogMessage::Flush()
> @ 0x2b232dc952e9 google::LogMessageFatal::~LogMessageFatal()
> @ 0x5803fa mesos::internal::tests::TestContainerizer::destroy()
> @ 0x2b232d88fda0 mesos::internal::slave::Slave::shutdownExecutorTimeout()
> @ 0x2b232dbc62c2 process::ProcessManager::resume()
> @ 0x2b232dbc65bc process::schedule()
> @ 0x2b232f68af6e start_thread
> @ 0x2b232f99a9cd (unknown)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)