[
https://issues.apache.org/jira/browse/MESOS-777?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vinod Kone resolved MESOS-777.
------------------------------
Resolution: Fixed
Assignee: Vinod Kone
commit 932fc9fd88081e784642e9b53138a437dd7fdd21
Author: Vinod Kone <[email protected]>
Date: Fri Oct 25 14:12:26 2013 -0700
Fixed GarbageCollectorIntegrationTest.ExitedFramework test.
Review: https://reviews.apache.org/r/14944
> GarbageCollectorIntegrationTest.ExitedFramework test is flaky
> -------------------------------------------------------------
>
> Key: MESOS-777
> URL: https://issues.apache.org/jira/browse/MESOS-777
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Assignee: Vinod Kone
> Fix For: 0.15.0
>
>
> [ RUN ] GarbageCollectorIntegrationTest.ExitedFramework
> I1025 09:46:27.381060 13134 master.cpp:284] Master started on 127.0.1.1:58170
> I1025 09:46:27.381099 13134 master.cpp:299] Master ID:
> 201310250946-16842879-58170-13114
> I1025 09:46:27.381106 13134 master.cpp:302] Master only allowing
> authenticated frameworks to register!
> I1025 09:46:27.381449 13134 master.cpp:697] Elected as master!
> I1025 09:46:27.381556 13134 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]:58170
> I1025 09:46:27.381589 13134 master.cpp:85] No whitelist given. Advertising
> offers for all slaves
> I1025 09:46:27.382287 13136 slave.cpp:109] Slave started on
> 86)@127.0.1.1:58170
> I1025 09:46:27.382391 13136 slave.cpp:209] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1025 09:46:27.382776 13136 slave.cpp:481] New master detected at
> [email protected]:58170
> I1025 09:46:27.382797 13136 slave.cpp:496] Postponing registration until
> recovery is complete
> I1025 09:46:27.382930 13136 status_update_manager.cpp:158] New master
> detected at [email protected]:58170
> I1025 09:46:27.382982 13136 state.cpp:33] Recovering state from
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fKJTrM/meta'
> I1025 09:46:27.383116 13136 status_update_manager.cpp:180] Recovering status
> update manager
> I1025 09:46:27.383286 13136 slave.cpp:2733] Finished recovery
> I1025 09:46:27.383430 13136 master.cpp:1223] Attempting to register slave on
> lucid at slave(86)@127.0.1.1:58170
> I1025 09:46:27.383445 13136 master.cpp:2481] Adding slave
> 201310250946-16842879-58170-13114-0 at lucid with cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000]
> I1025 09:46:27.383564 13136 slave.cpp:547] Registered with master
> [email protected]:58170; given slave ID 201310250946-16842879-58170-13114-0
> I1025 09:46:27.383622 13136 hierarchical_allocator_process.hpp:445] Added
> slave 201310250946-16842879-58170-13114-0 (lucid) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I1025 09:46:27.383656 13136 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 201310250946-16842879-58170-13114-0 in 6901ns
> I1025 09:46:27.384501 13134 sched.cpp:195] New master at
> [email protected]:58170
> I1025 09:46:27.384523 13134 sched.cpp:281] Authenticating with master
> [email protected]:58170
> I1025 09:46:27.384621 13134 authenticatee.hpp:124] Creating new client SASL
> connection
> I1025 09:46:27.384681 13134 master.cpp:1702] Authenticating framework at
> scheduler(63)@127.0.1.1:58170
> I1025 09:46:27.384805 13134 authenticator.hpp:140] Creating new server SASL
> connection
> I1025 09:46:27.384868 13134 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I1025 09:46:27.384881 13134 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1025 09:46:27.384910 13134 authenticator.hpp:243] Received SASL
> authentication start
> I1025 09:46:27.384953 13134 authenticator.hpp:325] Authentication requires
> more steps
> I1025 09:46:27.384975 13134 authenticatee.hpp:258] Received SASL
> authentication step
> I1025 09:46:27.385010 13134 authenticator.hpp:271] Received SASL
> authentication step
> I1025 09:46:27.385025 13134 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1025 09:46:27.385031 13134 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1025 09:46:27.385040 13134 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1025 09:46:27.385048 13134 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1025 09:46:27.385053 13134 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1025 09:46:27.385057 13134 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1025 09:46:27.385068 13134 authenticator.hpp:317] Authentication success
> I1025 09:46:27.385092 13134 authenticatee.hpp:298] Authentication success
> I1025 09:46:27.385123 13134 master.cpp:1742] Successfully authenticated
> framework at scheduler(63)@127.0.1.1:58170
> I1025 09:46:27.385177 13134 sched.cpp:326] Successfully authenticated with
> master [email protected]:58170
> I1025 09:46:27.385264 13134 master.cpp:755] Received registration request
> from scheduler(63)@127.0.1.1:58170
> I1025 09:46:27.385310 13134 master.cpp:773] Registering framework
> 201310250946-16842879-58170-13114-0000 at scheduler(63)@127.0.1.1:58170
> I1025 09:46:27.385372 13134 sched.cpp:365] Framework registered with
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.385392 13134 sched.cpp:379] Scheduler::registered took 8426ns
> I1025 09:46:27.385417 13134 hierarchical_allocator_process.hpp:332] Added
> framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.385448 13134 hierarchical_allocator_process.hpp:752] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 201310250946-16842879-58170-13114-0 to framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.385532 13134 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 104504ns
> I1025 09:46:27.385579 13134 master.hpp:413] Adding offer
> 201310250946-16842879-58170-13114-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.385615 13134 master.cpp:1668] Sending 1 offers to framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.385800 13134 sched.cpp:472] Scheduler::resourceOffers took
> 108896ns
> I1025 09:46:27.385886 13134 master.cpp:1994] Processing reply for offer
> 201310250946-16842879-58170-13114-0 on slave
> 201310250946-16842879-58170-13114-0 (lucid) for framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.385956 13134 master.hpp:385] Adding task 0 with resources
> cpus(*):2; mem(*):1024 on slave 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.385978 13134 master.cpp:2118] Launching task 0 of framework
> 201310250946-16842879-58170-13114-0000 with resources cpus(*):2; mem(*):1024
> on slave 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.386061 13134 master.hpp:423] Removing offer
> 201310250946-16842879-58170-13114-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.386132 13134 slave.cpp:720] Got assigned task 0 for framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.386281 13134 slave.cpp:831] Launching task 0 for framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.387634 13134 slave.cpp:941] Queuing task '0' for executor
> default of framework '201310250946-16842879-58170-13114-0000
> I1025 09:46:27.387686 13134 hierarchical_allocator_process.hpp:547] Framework
> 201310250946-16842879-58170-13114-0000 left disk(*):1024;
> ports(*):[31000-32000] unused on slave 201310250946-16842879-58170-13114-0
> I1025 09:46:27.387737 13134 hierarchical_allocator_process.hpp:590] Framework
> 201310250946-16842879-58170-13114-0000 filtered slave
> 201310250946-16842879-58170-13114-0 for 5secs
> I1025 09:46:27.388486 13137 slave.cpp:463] Successfully attached file
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fKJTrM/slaves/201310250946-16842879-58170-13114-0/frameworks/201310250946-16842879-58170-13114-0000/executors/default/runs/15e43a8b-a6a2-4665-be5d-e746ce44d277'
> I1025 09:46:27.389822 13135 exec.cpp:174] Executor started at:
> executor(22)@127.0.1.1:58170 with pid 13114
> I1025 09:46:27.389883 13135 slave.cpp:1403] Got registration for executor
> 'default' of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.389976 13135 slave.cpp:1524] Flushing queued task 0 for
> executor 'default' of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.390043 13135 exec.cpp:198] Executor registered on slave
> 201310250946-16842879-58170-13114-0
> I1025 09:46:27.390997 13135 exec.cpp:210] Executor::registered took 18303ns
> I1025 09:46:27.391057 13135 exec.cpp:285] Executor asked to run task '0'
> I1025 09:46:27.391284 13135 exec.cpp:294] Executor::launchTask took 216459ns
> I1025 09:46:27.392679 13135 exec.cpp:505] Executor sending status update
> TASK_RUNNING (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0 of
> framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.393053 13136 slave.cpp:1737] Handling status update
> TASK_RUNNING (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0 of
> framework 201310250946-16842879-58170-13114-0000 from
> executor(22)@127.0.1.1:58170
> I1025 09:46:27.393183 13136 status_update_manager.cpp:305] Received status
> update TASK_RUNNING (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0
> of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.393198 13136 status_update_manager.cpp:476] Creating
> StatusUpdate stream for task 0 of framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.393252 13136 status_update_manager.cpp:356] Forwarding status
> update TASK_RUNNING (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0
> of framework 201310250946-16842879-58170-13114-0000 to [email protected]:58170
> I1025 09:46:27.393381 13136 master.cpp:1425] Status update TASK_RUNNING
> (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0 of framework
> 201310250946-16842879-58170-13114-0000 from slave(86)@127.0.1.1:58170
> I1025 09:46:27.393465 13136 slave.cpp:1856] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0 of framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.393478 13136 slave.cpp:1862] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for
> task 0 of framework 201310250946-16842879-58170-13114-0000 to
> executor(22)@127.0.1.1:58170
> I1025 09:46:27.393548 13136 sched.cpp:527] Scheduler::statusUpdate took
> 15224ns
> I1025 09:46:27.393682 13136 status_update_manager.cpp:380] Received status
> update acknowledgement (UUID: 6a3cb008-2b72-43ee-8328-07e70d921172) for task
> 0 of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.393759 13136 slave.cpp:1343] Status update manager
> successfully handled status update acknowledgement (UUID:
> 6a3cb008-2b72-43ee-8328-07e70d921172) for task 0 of framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394116 13136 sched.cpp:630] Stopping framework
> '201310250946-16842879-58170-13114-0000'
> I1025 09:46:27.394232 13136 master.cpp:953] Asked to unregister framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394243 13136 master.cpp:2353] Removing framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394292 13136 master.hpp:403] Removing task 0 with resources
> cpus(*):2; mem(*):1024 on slave 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.394398 13136 hierarchical_allocator_process.hpp:408]
> Deactivated framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394446 13136 hierarchical_allocator_process.hpp:637] Recovered
> cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024;
> ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave
> 201310250946-16842879-58170-13114-0 from framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394487 13136 hierarchical_allocator_process.hpp:363] Removed
> framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394508 13136 slave.cpp:1119] Asked to shut down framework
> 201310250946-16842879-58170-13114-0000 by [email protected]:58170
> I1025 09:46:27.394518 13136 slave.cpp:1144] Shutting down framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394529 13136 slave.cpp:2396] Shutting down executor 'default'
> of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.394844 13135 exec.cpp:331] Executor received status update
> acknowledgement 6a3cb008-2b72-43ee-8328-07e70d921172 for task 0 of framework
> 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.395035 13135 exec.cpp:371] Executor asked to shutdown
> W1025 09:46:27.395310 13137 slave.cpp:2042] Killing executor 'default' of
> framework '201310250946-16842879-58170-13114-0000' because the framework is
> terminating
> I1025 09:46:27.400169 13135 exec.cpp:386] Executor::shutdown took 4.880173ms
> I1025 09:46:27.400607 13134 slave.cpp:2119] Executor 'default' of framework
> 201310250946-16842879-58170-13114-0000 has exited with status 0
> I1025 09:46:27.400681 13134 slave.cpp:2254] Cleaning up executor 'default' of
> framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.400821 13134 slave.cpp:2325] Cleaning up framework
> 201310250946-16842879-58170-13114-0000
> E1025 09:46:27.400992 13134 slave.cpp:2384] Failed to unwatch executor
> default of framework 201310250946-16842879-58170-13114-0000: Not watched
> W1025 09:46:27.401043 13134 master.cpp:1489] Ignoring unknown exited executor
> default on slave 201310250946-16842879-58170-13114-0 (lucid)
> I1025 09:46:27.401062 13134 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fKJTrM/slaves/201310250946-16842879-58170-13114-0/frameworks/201310250946-16842879-58170-13114-0000/executors/default/runs/15e43a8b-a6a2-4665-be5d-e746ce44d277'
> for gc
> I1025 09:46:27.401105 13134 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fKJTrM/slaves/201310250946-16842879-58170-13114-0/frameworks/201310250946-16842879-58170-13114-0000/executors/default'
> for gc
> I1025 09:46:27.401137 13134 gc.cpp:56] Scheduling
> '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_fKJTrM/slaves/201310250946-16842879-58170-13114-0/frameworks/201310250946-16842879-58170-13114-0000'
> for gc
> I1025 09:46:27.401167 13134 status_update_manager.cpp:267] Closing status
> update streams for framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.401181 13134 status_update_manager.cpp:507] Cleaning up status
> update stream for task 0 of framework 201310250946-16842879-58170-13114-0000
> I1025 09:46:27.411975 13134 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 20409ns
> I1025 09:46:27.412030 13135 slave.cpp:2431] Framework
> 201310250946-16842879-58170-13114-0000 seems to have exited. Ignoring
> shutdown timeout for executor 'default'
> I1025 09:46:27.412147 13137 master.cpp:85] No whitelist given. Advertising
> offers for all slaves
> Shutting down
> I1025 09:46:28.256333 13138 process.cpp:986] Socket closed while receiving
--
This message was sent by Atlassian JIRA
(v6.1#6144)
