Description
[ RUN ] StatusUpdateManagerTest.DuplicateTerminalUpdateBeforeAck
I1024 23:16:41.950958 11103 master.cpp:284] Master started on 67.195.138.9:56035
I1024 23:16:41.950990 11103 master.cpp:299] Master ID: 201310242316-160088899-56035-11083
I1024 23:16:41.950997 11103 master.cpp:302] Master only allowing authenticated frameworks to register!
I1024 23:16:41.951199 11102 master.cpp:85] No whitelist given. Advertising offers for all slaves
I1024 23:16:41.951246 11107 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@67.195.138.9:56035
I1024 23:16:41.951457 11103 master.cpp:697] Elected as master!
I1024 23:16:41.952445 11106 slave.cpp:109] Slave started on 130)@67.195.138.9:56035
I1024 23:16:41.952533 11106 slave.cpp:209] Slave resources: cpus
:2; mem:1024; disk:1024; ports:[31000-32000]
I1024 23:16:41.952764 11109 sched.cpp:195] New master at master@67.195.138.9:56035
I1024 23:16:41.952787 11109 sched.cpp:281] Authenticating with master master@67.195.138.9:56035
I1024 23:16:41.952873 11109 authenticatee.hpp:124] Creating new client SASL connection
I1024 23:16:41.952925 11109 master.cpp:1702] Authenticating framework at scheduler(124)@67.195.138.9:56035
I1024 23:16:41.953085 11107 authenticator.hpp:140] Creating new server SASL connection
I1024 23:16:41.953145 11109 state.cpp:33] Recovering state from '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta'
I1024 23:16:41.953157 11107 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1024 23:16:41.953179 11107 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1024 23:16:41.953208 11107 authenticator.hpp:243] Received SASL authentication start
I1024 23:16:41.953260 11107 authenticator.hpp:325] Authentication requires more steps
I1024 23:16:41.953305 11109 authenticatee.hpp:258] Received SASL authentication step
I1024 23:16:41.953352 11109 authenticator.hpp:271] Received SASL authentication step
I1024 23:16:41.953359 11106 slave.cpp:481] New master detected at master@67.195.138.9:56035
I1024 23:16:41.953372 11109 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1024 23:16:41.953380 11109 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1024 23:16:41.953382 11106 slave.cpp:496] Postponing registration until recovery is complete
I1024 23:16:41.953398 11109 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1024 23:16:41.953399 11107 status_update_manager.cpp:158] New master detected at master@67.195.138.9:56035
I1024 23:16:41.953408 11109 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1024 23:16:41.953430 11109 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1024 23:16:41.953435 11109 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1024 23:16:41.953446 11109 authenticator.hpp:317] Authentication success
I1024 23:16:41.953449 11107 status_update_manager.cpp:180] Recovering status update manager
I1024 23:16:41.953534 11105 authenticatee.hpp:298] Authentication success
I1024 23:16:41.953536 11108 master.cpp:1742] Successfully authenticated framework at scheduler(124)@67.195.138.9:56035
I1024 23:16:41.953665 11103 sched.cpp:326] Successfully authenticated with master master@67.195.138.9:56035
I1024 23:16:41.953798 11108 master.cpp:755] Received registration request from scheduler(124)@67.195.138.9:56035
I1024 23:16:41.953994 11108 master.cpp:773] Registering framework 201310242316-160088899-56035-11083-0000 at scheduler(124)@67.195.138.9:56035
I1024 23:16:41.954087 11109 sched.cpp:365] Framework registered with 201310242316-160088899-56035-11083-0000
I1024 23:16:41.954113 11105 hierarchical_allocator_process.hpp:332] Added framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.954123 11106 slave.cpp:2733] Finished recovery
I1024 23:16:41.954129 11105 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I1024 23:16:41.954139 11105 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 11250ns
I1024 23:16:41.954116 11109 sched.cpp:379] Scheduler::registered took 10300ns
I1024 23:16:41.954269 11102 master.cpp:1223] Attempting to register slave on vesta.apache.org at slave(130)@67.195.138.9:56035
I1024 23:16:41.954294 11102 master.cpp:2481] Adding slave 201310242316-160088899-56035-11083-0 at vesta.apache.org with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1024 23:16:41.954391 11104 slave.cpp:547] Registered with master master@67.195.138.9:56035; given slave ID 201310242316-160088899-56035-11083-0
I1024 23:16:41.954483 11107 hierarchical_allocator_process.hpp:445] Added slave 201310242316-160088899-56035-11083-0 (vesta.apache.org) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (and cpus:2; mem:1024; disk:1024; ports:[31000-32000] available)
I1024 23:16:41.954550 11107 hierarchical_allocator_process.hpp:752] Offering cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 to framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.954668 11107 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201310242316-160088899-56035-11083-0 in 145998ns
I1024 23:16:41.954711 11108 master.hpp:413] Adding offer 201310242316-160088899-56035-11083-0 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:41.954752 11108 master.cpp:1668] Sending 1 offers to framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.954869 11105 sched.cpp:472] Scheduler::resourceOffers took 24452ns
I1024 23:16:41.955461 11102 master.cpp:1994] Processing reply for offer 201310242316-160088899-56035-11083-0 on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org) for framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.955613 11102 master.hpp:385] Adding task 1 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:41.955636 11104 slave.cpp:560] Checkpointing SlaveInfo to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/slave.info'
I1024 23:16:41.955662 11102 master.cpp:2118] Launching task 1 of framework 201310242316-160088899-56035-11083-0000 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:41.955795 11104 slave.cpp:720] Got assigned task 1 for framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.955800 11102 master.hpp:423] Removing offer 201310242316-160088899-56035-11083-0 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:41.955883 11104 slave.cpp:2878] Checkpointing FrameworkInfo to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/framework.info'
I1024 23:16:41.962931 11104 slave.cpp:2885] Checkpointing framework pid 'scheduler(124)@67.195.138.9:56035' to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/framework.pid'
I1024 23:16:41.963119 11104 slave.cpp:831] Launching task 1 for framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.964717 11104 slave.cpp:3110] Checkpointing ExecutorInfo to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/executors/default/executor.info'
I1024 23:16:41.965172 11104 slave.cpp:3199] Checkpointing TaskInfo to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/executors/default/runs/3056bd6a-c5d8-4c1a-a5b2-9cc0cc82e11e/tasks/1/task.info'
I1024 23:16:41.965422 11104 slave.cpp:941] Queuing task '1' for executor default of framework '201310242316-160088899-56035-11083-0000
I1024 23:16:41.965466 11104 slave.cpp:463] Successfully attached file '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/executors/default/runs/3056bd6a-c5d8-4c1a-a5b2-9cc0cc82e11e'
I1024 23:16:41.966447 11108 exec.cpp:174] Executor started at: executor(39)@67.195.138.9:56035 with pid 11083
I1024 23:16:41.966578 11108 slave.cpp:1403] Got registration for executor 'default' of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.966611 11108 slave.cpp:1488] Checkpointing executor pid 'executor(39)@67.195.138.9:56035' to '/tmp/StatusUpdateManagerTest_DuplicateTerminalUpdateBeforeAck_M7nsgM/meta/slaves/201310242316-160088899-56035-11083-0/frameworks/201310242316-160088899-56035-11083-0000/executors/default/runs/3056bd6a-c5d8-4c1a-a5b2-9cc0cc82e11e/pids/libprocess.pid'
I1024 23:16:41.967216 11108 slave.cpp:1524] Flushing queued task 1 for executor 'default' of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.967353 11102 exec.cpp:198] Executor registered on slave 201310242316-160088899-56035-11083-0
I1024 23:16:41.968533 11102 exec.cpp:210] Executor::registered took 15746ns
I1024 23:16:41.968597 11102 exec.cpp:285] Executor asked to run task '1'
I1024 23:16:41.968641 11102 exec.cpp:294] Executor::launchTask took 29005ns
I1024 23:16:41.969707 11102 exec.cpp:505] Executor sending status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.969787 11102 slave.cpp:1737] Handling status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 from executor(39)@67.195.138.9:56035
I1024 23:16:41.969818 11102 slave.cpp:3155] Terminating task 1
I1024 23:16:41.969985 11102 status_update_manager.cpp:305] Received status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.970005 11102 status_update_manager.cpp:476] Creating StatusUpdate stream for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:41.970160 11102 status_update_manager.hpp:337] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.059442 11102 status_update_manager.cpp:356] Forwarding status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 to master@67.195.138.9:56035
I1024 23:16:42.059660 11109 master.cpp:1425] Status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 from slave(130)@67.195.138.9:56035
I1024 23:16:42.059748 11106 sched.cpp:527] Scheduler::statusUpdate took 24889ns
I1024 23:16:42.059736 11109 master.hpp:403] Removing task 1 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:42.059927 11106 hierarchical_allocator_process.hpp:637] Recovered cpus:2; mem:1024; disk:1024; ports:[31000-32000] (total allocatable: cpus:2; mem:1024; disk:1024; ports:[31000-32000]) on slave 201310242316-160088899-56035-11083-0 from framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.060192 11106 slave.cpp:1856] Status update manager successfully handled status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.060210 11106 slave.cpp:1862] Sending acknowledgement for status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 to executor(39)@67.195.138.9:56035
I1024 23:16:42.060647 11105 master.cpp:85] No whitelist given. Advertising offers for all slaves
W1024 23:16:42.060717 11104 status_update_manager.cpp:459] Resending status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.060732 11104 status_update_manager.cpp:356] Forwarding status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 to master@67.195.138.9:56035
I1024 23:16:42.060740 11105 monitor.cpp:187] Publishing resource usage for executor 'default' of framework '201310242316-160088899-56035-11083-0000'
W1024 23:16:42.060850 11103 master.cpp:1418] Status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000 from slave(130)@67.195.138.9:56035 (vesta.apache.org): error, couldn't lookup task
I1024 23:16:42.060874 11105 monitor.cpp:187] Publishing resource usage for executor 'default' of framework '201310242316-160088899-56035-11083-0000'
I1024 23:16:42.060905 11106 sched.cpp:527] Scheduler::statusUpdate took 23685ns
I1024 23:16:42.061041 11106 status_update_manager.cpp:380] Received status update acknowledgement (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061049 11102 hierarchical_allocator_process.hpp:752] Offering cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 to framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061058 11106 status_update_manager.hpp:337] Checkpointing ACK for status update TASK_FINISHED (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061171 11102 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 276168ns
I1024 23:16:42.061238 11105 master.hpp:413] Adding offer 201310242316-160088899-56035-11083-1 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:42.061306 11105 master.cpp:1668] Sending 1 offers to framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061357 11109 exec.cpp:505] Executor sending status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061414 11109 exec.cpp:331] Executor received status update acknowledgement 258c8b04-f7c8-4b4b-a89a-e035b30e0955 for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.061434 11103 sched.cpp:472] Scheduler::resourceOffers took 9810ns
I1024 23:16:42.061488 11102 slave.cpp:1737] Handling status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000 from executor(39)@67.195.138.9:56035
I1024 23:16:42.079542 11106 status_update_manager.cpp:507] Cleaning up status update stream for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.079645 11106 status_update_manager.cpp:305] Received status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.079655 11106 status_update_manager.cpp:476] Creating StatusUpdate stream for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.079749 11106 status_update_manager.hpp:337] Checkpointing UPDATE for status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.079838 11102 slave.cpp:1343] Status update manager successfully handled status update acknowledgement (UUID: 258c8b04-f7c8-4b4b-a89a-e035b30e0955) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.079849 11102 slave.cpp:3178] Completing task 1
I1024 23:16:42.095638 11106 status_update_manager.cpp:356] Forwarding status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000 to master@67.195.138.9:56035
I1024 23:16:42.095782 11102 slave.cpp:1856] Status update manager successfully handled status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
W1024 23:16:42.095782 11106 master.cpp:1418] Status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000 from slave(130)@67.195.138.9:56035 (vesta.apache.org): error, couldn't lookup task
I1024 23:16:42.095795 11102 slave.cpp:1862] Sending acknowledgement for status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000 to executor(39)@67.195.138.9:56035
I1024 23:16:42.095886 11102 exec.cpp:331] Executor received status update acknowledgement 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad for task 1 of framework 201310242316-160088899-56035-11083-0000
../../src/tests/status_update_manager_tests.cpp:550: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fff2c8c3d10, @0x2acc5802e970 64-byte object <90-71 D3-2D CC-2A 00-00 00-00 00-00 00-00 00-00 F0-64 03-58 CC-2A 00-00 88-0D C3-00 00-00 00-00 88-0D C3-00 00-00 00-00 C0-70 02-58 CC-2A 00-00 04-00 00-00 00-00 00-00 13-00 00-00 00-2A 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I1024 23:16:42.095988 11109 sched.cpp:527] Scheduler::statusUpdate took 142429ns
I1024 23:16:42.096127 11109 status_update_manager.cpp:380] Received status update acknowledgement (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.096146 11109 status_update_manager.hpp:337] Checkpointing ACK for status update TASK_KILLED (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.173617 11109 status_update_manager.cpp:507] Cleaning up status update stream for task 1 of framework 201310242316-160088899-56035-11083-0000
I1024 23:16:42.173754 11109 slave.cpp:1343] Status update manager successfully handled status update acknowledgement (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of framework 201310242316-160088899-56035-11083-0000
E1024 23:16:42.173768 11109 slave.cpp:1367] Status update acknowledgement (UUID: 4a94b5ff-9699-48cd-ab40-7eaed5f1bfad) for task 1 of unknown executor
I1024 23:16:42.181135 11109 sched.cpp:630] Stopping framework '201310242316-160088899-56035-11083-0000'
I1024 23:16:42.181159 11083 master.cpp:557] Master terminating
I1024 23:16:42.181193 11083 master.cpp:209] Shutting down master
I1024 23:16:42.181210 11105 slave.cpp:1937] master@67.195.138.9:56035 exited
W1024 23:16:42.181221 11105 slave.cpp:1940] Master disconnected! Waiting for a new master to be elected
I1024 23:16:42.181241 11083 master.hpp:423] Removing offer 201310242316-160088899-56035-11083-1 with resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] on slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:42.181341 11083 master.cpp:252] Removing slave 201310242316-160088899-56035-11083-0 (vesta.apache.org)
I1024 23:16:42.181654 11083 slave.cpp:388] Slave terminating
I1024 23:16:42.181882 11106 exec.cpp:431] Slave exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with slave 201310242316-160088899-56035-11083-0
[ FAILED ] StatusUpdateManagerTest.DuplicateTerminalUpdateBeforeAck (232 ms)
Attachments
Issue Links
- duplicates
-
MESOS-773 StatusUpdateManagerTest.DuplicateTerminalUpdateBeforeAck is flaky
-
- Resolved
-