[
https://issues.apache.org/jira/browse/MESOS-985?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13897402#comment-13897402
]
Vinod Kone commented on MESOS-985:
----------------------------------
https://reviews.apache.org/r/17928/
> FaultToleranceTest.IgnoreKillTaskFromUnregisteredFramework is flaky
> -------------------------------------------------------------------
>
> Key: MESOS-985
> URL: https://issues.apache.org/jira/browse/MESOS-985
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 0.18.0
> Reporter: Vinod Kone
> Assignee: Vinod Kone
> Fix For: 0.18.0
>
>
> [ RUN ] FaultToleranceTest.IgnoreKillTaskFromUnregisteredFramework
> I0210 16:47:28.314275 27200 master.cpp:285] Master started on 127.0.0.1:33802
> I0210 16:47:28.314314 27200 master.cpp:300] Master ID:
> 201402101647-16777343-33802-27175
> I0210 16:47:28.314322 27200 master.cpp:303] Master only allowing
> authenticated frameworks to register!
> I0210 16:47:28.314806 27200 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]:33802
> I0210 16:47:28.314843 27200 master.cpp:86] No whitelist given. Advertising
> offers for all slaves
> I0210 16:47:28.314975 27200 master.cpp:738] The newly elected leader is
> [email protected]:33802
> I0210 16:47:28.314986 27200 master.cpp:746] Elected as the leading master!
> I0210 16:47:28.316339 27199 slave.cpp:112] Slave started on
> 110)@127.0.0.1:33802
> I0210 16:47:28.316421 27199 slave.cpp:212] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0210 16:47:28.316964 27199 state.cpp:33] Recovering state from
> '/tmp/FaultToleranceTest_IgnoreKillTaskFromUnregisteredFramework_oWtPdM/meta'
> I0210 16:47:28.317072 27199 sched.cpp:210] New master detected at
> [email protected]:33802
> I0210 16:47:28.317091 27199 sched.cpp:261] Authenticating with master
> [email protected]:33802
> I0210 16:47:28.317131 27199 sched.cpp:230] Detecting new master
> I0210 16:47:28.317159 27199 status_update_manager.cpp:188] Recovering status
> update manager
> I0210 16:47:28.317206 27199 authenticatee.hpp:124] Creating new client SASL
> connection
> I0210 16:47:28.317301 27199 master.cpp:2299] Authenticating framework at
> scheduler(91)@127.0.0.1:33802
> I0210 16:47:28.317376 27199 slave.cpp:2753] Finished recovery
> I0210 16:47:28.317675 27197 authenticator.hpp:140] Creating new server SASL
> connection
> I0210 16:47:28.317738 27197 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0210 16:47:28.317751 27197 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0210 16:47:28.317775 27197 authenticator.hpp:243] Received SASL
> authentication start
> I0210 16:47:28.317814 27197 authenticator.hpp:325] Authentication requires
> more steps
> I0210 16:47:28.317839 27197 authenticatee.hpp:258] Received SASL
> authentication step
> I0210 16:47:28.317872 27197 authenticator.hpp:271] Received SASL
> authentication step
> I0210 16:47:28.317888 27197 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'localhost.localdomain' server FQDN:
> 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
> false
> I0210 16:47:28.317895 27197 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0210 16:47:28.317905 27197 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0210 16:47:28.317914 27197 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'localhost.localdomain' server FQDN:
> 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
> true
> I0210 16:47:28.317920 27197 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0210 16:47:28.317926 27197 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0210 16:47:28.317937 27197 authenticator.hpp:317] Authentication success
> I0210 16:47:28.317961 27197 authenticatee.hpp:298] Authentication success
> I0210 16:47:28.317982 27197 master.cpp:2339] Successfully authenticated
> framework at scheduler(91)@127.0.0.1:33802
> I0210 16:47:28.318042 27197 sched.cpp:335] Successfully authenticated with
> master [email protected]:33802
> I0210 16:47:28.318088 27197 master.cpp:794] Received registration request
> from scheduler(91)@127.0.0.1:33802
> I0210 16:47:28.318109 27197 master.cpp:812] Registering framework
> 201402101647-16777343-33802-27175-0000 at scheduler(91)@127.0.0.1:33802
> I0210 16:47:28.318158 27197 sched.cpp:384] Framework registered with
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.318179 27197 sched.cpp:398] Scheduler::registered took 8273ns
> I0210 16:47:28.318207 27197 hierarchical_allocator_process.hpp:332] Added
> framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.318215 27197 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0210 16:47:28.318222 27197 hierarchical_allocator_process.hpp:688] Performed
> allocation for 0 slaves in 6478ns
> I0210 16:47:28.318552 27199 slave.cpp:501] New master detected at
> [email protected]:33802
> I0210 16:47:28.318971 27199 slave.cpp:526] Detecting new master
> I0210 16:47:28.319080 27199 status_update_manager.cpp:162] New master
> detected at [email protected]:33802
> I0210 16:47:28.319322 27199 master.cpp:1816] Attempting to register slave on
> localhost.localdomain at slave(110)@127.0.0.1:33802
> I0210 16:47:28.319632 27199 master.cpp:2786] Adding slave
> 201402101647-16777343-33802-27175-0 at localhost.localdomain with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0210 16:47:28.319936 27197 slave.cpp:544] Registered with master
> [email protected]:33802; given slave ID 201402101647-16777343-33802-27175-0
> I0210 16:47:28.320317 27197 hierarchical_allocator_process.hpp:445] Added
> slave 201402101647-16777343-33802-27175-0 (localhost.localdomain) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0210 16:47:28.320374 27197 hierarchical_allocator_process.hpp:752] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 201402101647-16777343-33802-27175-0 to framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.320463 27197 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 201402101647-16777343-33802-27175-0 in 109544ns
> I0210 16:47:28.320691 27199 master.hpp:431] Adding offer
> 201402101647-16777343-33802-27175-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 201402101647-16777343-33802-27175-0 (localhost.localdomain)
> I0210 16:47:28.320945 27199 master.cpp:2254] Sending 1 offers to framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.321365 27198 sched.cpp:518] Scheduler::resourceOffers took
> 127195ns
> I0210 16:47:28.321665 27199 master.hpp:441] Removing offer
> 201402101647-16777343-33802-27175-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 201402101647-16777343-33802-27175-0 (localhost.localdomain)
> I0210 16:47:28.321925 27199 master.cpp:1550] Processing reply for offers: [
> 201402101647-16777343-33802-27175-0 ] on slave
> 201402101647-16777343-33802-27175-0 (localhost.localdomain) for framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.322175 27199 master.hpp:403] Adding task 0 with resources
> cpus(*):1; mem(*):512 on slave 201402101647-16777343-33802-27175-0
> (localhost.localdomain)
> I0210 16:47:28.322388 27199 master.cpp:2423] Launching task 0 of framework
> 201402101647-16777343-33802-27175-0000 with resources cpus(*):1; mem(*):512
> on slave 201402101647-16777343-33802-27175-0 (localhost.localdomain)
> I0210 16:47:28.322751 27196 slave.cpp:729] Got assigned task 0 for framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.322907 27196 slave.cpp:838] Launching task 0 for framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.325883 27196 slave.cpp:948] Queuing task '0' for executor
> default of framework '201402101647-16777343-33802-27175-0000
> I0210 16:47:28.326372 27196 slave.cpp:466] Successfully attached file
> '/tmp/FaultToleranceTest_IgnoreKillTaskFromUnregisteredFramework_oWtPdM/slaves/201402101647-16777343-33802-27175-0/frameworks/201402101647-16777343-33802-27175-0000/executors/default/runs/645369af-2374-45e2-baea-ef722717f461'
> I0210 16:47:28.327816 27198 exec.cpp:178] Executor started at:
> executor(34)@127.0.0.1:33802 with pid 27175
> I0210 16:47:28.327880 27197 slave.cpp:1424] Got registration for executor
> 'default' of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.327960 27197 slave.cpp:1545] Flushing queued task 0 for
> executor 'default' of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.328025 27197 exec.cpp:202] Executor registered on slave
> 201402101647-16777343-33802-27175-0
> I0210 16:47:28.329026 27197 exec.cpp:214] Executor::registered took 16316ns
> I0210 16:47:28.329082 27197 exec.cpp:289] Executor asked to run task '0'
> I0210 16:47:28.329283 27198 hierarchical_allocator_process.hpp:547] Framework
> 201402101647-16777343-33802-27175-0000 left cpus(*):1; mem(*):512;
> disk(*):1024; ports(*):[31000-32000] unused on slave
> 201402101647-16777343-33802-27175-0
> I0210 16:47:28.329397 27198 hierarchical_allocator_process.hpp:590] Framework
> 201402101647-16777343-33802-27175-0000 filtered slave
> 201402101647-16777343-33802-27175-0 for 5secs
> I0210 16:47:28.329782 27197 exec.cpp:298] Executor::launchTask took 685284ns
> I0210 16:47:28.330807 27197 exec.cpp:521] Executor sending status update
> TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0 of
> framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.330996 27197 slave.cpp:1758] Handling status update
> TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0 of
> framework 201402101647-16777343-33802-27175-0000 from
> executor(34)@127.0.0.1:33802
> I0210 16:47:28.331171 27197 status_update_manager.cpp:314] Received status
> update TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0
> of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.331326 27197 status_update_manager.cpp:493] Creating
> StatusUpdate stream for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.331468 27197 status_update_manager.cpp:367] Forwarding status
> update TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0
> of framework 201402101647-16777343-33802-27175-0000 to [email protected]:33802
> I0210 16:47:28.331754 27197 master.cpp:2002] Status update TASK_RUNNING
> (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0 of framework
> 201402101647-16777343-33802-27175-0000 from slave(110)@127.0.0.1:33802
> I0210 16:47:28.331867 27197 slave.cpp:1877] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 774ad391-5824-436b-9996-55ccada6af81) for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.332947 27197 slave.cpp:1883] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for
> task 0 of framework 201402101647-16777343-33802-27175-0000 to
> executor(34)@127.0.0.1:33802
> I0210 16:47:28.332767 27195 sched.cpp:210] New master detected at
> [email protected]:33802
> I0210 16:47:28.333220 27195 sched.cpp:261] Authenticating with master
> [email protected]:33802
> I0210 16:47:28.333292 27195 sched.cpp:230] Detecting new master
> I0210 16:47:28.333341 27195 authenticatee.hpp:124] Creating new client SASL
> connection
> I0210 16:47:28.333413 27195 master.cpp:2299] Authenticating framework at
> scheduler(92)@127.0.0.1:33802
> I0210 16:47:28.333487 27195 authenticator.hpp:140] Creating new server SASL
> connection
> I0210 16:47:28.333542 27195 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0210 16:47:28.333561 27195 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0210 16:47:28.333644 27195 authenticator.hpp:243] Received SASL
> authentication start
> I0210 16:47:28.333689 27195 authenticator.hpp:325] Authentication requires
> more steps
> I0210 16:47:28.333717 27195 authenticatee.hpp:258] Received SASL
> authentication step
> I0210 16:47:28.333751 27195 authenticator.hpp:271] Received SASL
> authentication step
> I0210 16:47:28.333767 27195 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'localhost.localdomain' server FQDN:
> 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
> false
> I0210 16:47:28.333776 27195 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0210 16:47:28.333787 27195 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0210 16:47:28.333797 27195 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'localhost.localdomain' server FQDN:
> 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
> true
> I0210 16:47:28.333804 27195 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0210 16:47:28.333809 27195 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0210 16:47:28.333822 27195 authenticator.hpp:317] Authentication success
> I0210 16:47:28.333847 27195 authenticatee.hpp:298] Authentication success
> I0210 16:47:28.333894 27195 master.cpp:2339] Successfully authenticated
> framework at scheduler(92)@127.0.0.1:33802
> I0210 16:47:28.333958 27195 sched.cpp:335] Successfully authenticated with
> master [email protected]:33802
> I0210 16:47:28.334008 27195 master.cpp:882] Re-registering framework
> 201402101647-16777343-33802-27175-0000 at scheduler(92)@127.0.0.1:33802
> I0210 16:47:28.334022 27195 master.cpp:908] Framework
> 201402101647-16777343-33802-27175-0000 failed over
> I0210 16:47:28.334070 27195 sched.cpp:384] Framework registered with
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.334090 27195 sched.cpp:398] Scheduler::registered took 8071ns
> I0210 16:47:28.332135 27196 sched.cpp:609] Scheduler::statusUpdate took
> 17741ns
> I0210 16:47:28.334801 27196 master.cpp:1655] Asked to kill task 0 of
> framework 201402101647-16777343-33802-27175-0000
> W0210 16:47:28.334915 27196 master.cpp:1668] Ignoring kill task message for
> task 0 of framework 201402101647-16777343-33802-27175-0000 from
> 'scheduler(91)@127.0.0.1:33802' because it is not from the registered
> framework 'scheduler(92)@127.0.0.1:33802'
> I0210 16:47:28.336783 27200 exec.cpp:521] Executor sending status update
> TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0 of
> framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.337124 27197 slave.cpp:2091] Monitoring executor default of
> framework 201402101647-16777343-33802-27175-0000 forked at pid 27175
> I0210 16:47:28.337548 27197 slave.cpp:1305] Updating framework
> 201402101647-16777343-33802-27175-0000 pid to scheduler(92)@127.0.0.1:33802
> I0210 16:47:28.337986 27197 slave.cpp:1758] Handling status update
> TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0 of
> framework 201402101647-16777343-33802-27175-0000 from
> executor(34)@127.0.0.1:33802
> I0210 16:47:28.338248 27197 slave.cpp:3207] Terminating task 0
> W0210 16:47:28.338119 27196 status_update_manager.cpp:176] Resending status
> update TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0
> of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.338500 27196 status_update_manager.cpp:367] Forwarding status
> update TASK_RUNNING (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0
> of framework 201402101647-16777343-33802-27175-0000 to [email protected]:33802
> I0210 16:47:28.337339 27199 exec.cpp:335] Executor received status update
> acknowledgement 774ad391-5824-436b-9996-55ccada6af81 for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.338857 27198 master.cpp:2002] Status update TASK_RUNNING
> (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0 of framework
> 201402101647-16777343-33802-27175-0000 from slave(110)@127.0.0.1:33802
> I0210 16:47:28.338925 27198 sched.cpp:609] Scheduler::statusUpdate took
> 13726ns
> I0210 16:47:28.339025 27196 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task
> 0 of framework 201402101647-16777343-33802-27175-0000
> tests/fault_tolerance_tests.cpp:1499: Failure
> Value of: status2.get().state()
> Actual: TASK_RUNNING
> Expected: TASK_FINISHED
> I0210 16:47:28.339249 27175 master.cpp:565] Master terminating
> I0210 16:47:28.339272 27175 master.cpp:210] Shutting down master
> I0210 16:47:28.339306 27175 master.hpp:421] Removing task 0 with resources
> cpus(*):1; mem(*):512 on slave 201402101647-16777343-33802-27175-0
> (localhost.localdomain)
> I0210 16:47:28.339367 27175 master.cpp:253] Removing slave
> 201402101647-16777343-33802-27175-0 (localhost.localdomain)
> I0210 16:47:28.339643 27196 sched.cpp:720] Stopping framework
> '201402101647-16777343-33802-27175-0000'
> I0210 16:47:28.339690 27196 sched.cpp:720] Stopping framework
> '201402101647-16777343-33802-27175-0000'
> I0210 16:47:28.340121 27197 slave.cpp:1364] Status update manager
> successfully handled status update acknowledgement (UUID:
> 774ad391-5824-436b-9996-55ccada6af81) for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.340422 27197 slave.cpp:1958] [email protected]:33802 exited
> W0210 16:47:28.340677 27197 slave.cpp:1961] Master disconnected! Waiting for
> a new master to be elected
> I0210 16:47:28.340220 27196 status_update_manager.cpp:314] Received status
> update TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0
> of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.340899 27196 status_update_manager.cpp:367] Forwarding status
> update TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0
> of framework 201402101647-16777343-33802-27175-0000 to [email protected]:33802
> I0210 16:47:28.340978 27196 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task
> 0 of framework 201402101647-16777343-33802-27175-0000
> W0210 16:47:28.340996 27196 status_update_manager.hpp:259] Duplicate status
> update acknowledgment (UUID: 774ad391-5824-436b-9996-55ccada6af81) for update
> TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0 of
> framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.341030 27196 slave.cpp:1877] Status update manager
> successfully handled status update TASK_FINISHED (UUID:
> 071c1ff5-e724-44f0-9098-d15c886ca333) for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.341042 27196 slave.cpp:1883] Sending acknowledgement for
> status update TASK_FINISHED (UUID: 071c1ff5-e724-44f0-9098-d15c886ca333) for
> task 0 of framework 201402101647-16777343-33802-27175-0000 to
> executor(34)@127.0.0.1:33802
> E0210 16:47:28.341071 27196 slave.cpp:1357] Failed to handle status update
> acknowledgement (UUID: 774ad391-5824-436b-9996-55ccada6af81) for task 0 of
> framework 201402101647-16777343-33802-27175-0000: Duplicate acknowledgement
> I0210 16:47:28.341099 27196 exec.cpp:335] Executor received status update
> acknowledgement 071c1ff5-e724-44f0-9098-d15c886ca333 for task 0 of framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.355067 27175 slave.cpp:391] Slave terminating
> I0210 16:47:28.355098 27175 slave.cpp:1135] Asked to shut down framework
> 201402101647-16777343-33802-27175-0000 by @0.0.0.0:0
> I0210 16:47:28.355110 27175 slave.cpp:1160] Shutting down framework
> 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.355124 27175 slave.cpp:2424] Shutting down executor 'default'
> of framework 201402101647-16777343-33802-27175-0000
> I0210 16:47:28.355348 27175 exec.cpp:375] Executor asked to shutdown
> I0210 16:47:28.355371 27175 exec.cpp:390] Executor::shutdown took 8016ns
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
