[MESOS-6792] MasterSlaveReconciliationTest.ReconcileLostTask test is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Won't Fix
Affects Version/s: None
Fix Version/s: None
Component/s: None
Labels:
- flaky-test
- tech-debt
Environment:

Fedora 25, clang, w/ optimizations, SSL build

Description

The test MasterSlaveReconciliationTest.ReconcileLostTask is flaky for me as of e99ea9ce8b1de01dd8b3cac6675337edb6320f38,

Repeating all tests (iteration 912) . . .

Note: Google Test filter = <...>
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from MasterSlaveReconciliationTest
[ RUN      ] MasterSlaveReconciliationTest.SlaveReregisterTerminatedExecutor
I1214 04:41:11.559672  2005 cluster.cpp:160] Creating default 'local' authorizer
I1214 04:41:11.560848  2045 master.cpp:380] Master 87dd8179-dd7d-4270-ace2-ea771b57371c (gru1.hw.ca1.mesosphere.com) started on 192.99.40.208:37659
I1214 04:41:11.560878  2045 master.cpp:382] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/cXHI89/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/home/bbannier/src/mesos/build/P/share/mesos/webui" --work_dir="/tmp/cXHI89/master" --zk_session_timeout="10secs"
I1214 04:41:11.561079  2045 master.cpp:432] Master only allowing authenticated frameworks to register
I1214 04:41:11.561089  2045 master.cpp:446] Master only allowing authenticated agents to register
I1214 04:41:11.561095  2045 master.cpp:459] Master only allowing authenticated HTTP frameworks to register
I1214 04:41:11.561101  2045 credentials.hpp:39] Loading credentials for authentication from '/tmp/cXHI89/credentials'
I1214 04:41:11.561194  2045 master.cpp:504] Using default 'crammd5' authenticator
I1214 04:41:11.561236  2045 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I1214 04:41:11.561274  2045 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I1214 04:41:11.561301  2045 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I1214 04:41:11.561326  2045 master.cpp:584] Authorization enabled
I1214 04:41:11.562155  2039 master.cpp:2045] Elected as the leading master!
I1214 04:41:11.562173  2039 master.cpp:1568] Recovering from registrar
I1214 04:41:11.562347  2045 registrar.cpp:362] Successfully fetched the registry (0B) in 114944ns
I1214 04:41:11.562441  2045 registrar.cpp:461] Applied 1 operations in 7920ns; attempting to update the registry
I1214 04:41:11.562621  2048 registrar.cpp:506] Successfully updated the registry in 155136ns
I1214 04:41:11.562664  2048 registrar.cpp:392] Successfully recovered registrar
I1214 04:41:11.562832  2044 master.cpp:1684] Recovered 0 agents from the registry (166B); allowing 10mins for agents to re-register
I1214 04:41:11.568444  2005 cluster.cpp:446] Creating default 'local' authorizer
I1214 04:41:11.569344  2005 sched.cpp:232] Version: 1.2.0
I1214 04:41:11.569842  2035 slave.cpp:209] Mesos agent started on (912)@192.99.40.208:37659
I1214 04:41:11.570080  2040 sched.cpp:336] New master detected at master@192.99.40.208:37659
I1214 04:41:11.570117  2040 sched.cpp:402] Authenticating with master master@192.99.40.208:37659
I1214 04:41:11.570127  2040 sched.cpp:409] Using default CRAM-MD5 authenticatee
I1214 04:41:11.570220  2040 authenticatee.cpp:121] Creating new client SASL connection
I1214 04:41:11.570000  2035 slave.cpp:210] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf/http_credentials" --http_heartbeat_interval="30secs" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/home/bbannier/src/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_7badJc"
I1214 04:41:11.570297  2035 credentials.hpp:88] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf/credential'
I1214 04:41:11.570307  2040 master.cpp:6748] Authenticating scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.570351  2035 slave.cpp:352] Agent using credential for: test-principal
I1214 04:41:11.570363  2035 credentials.hpp:39] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Y63Hjf/http_credentials'
I1214 04:41:11.570405  2040 authenticator.cpp:98] Creating new server SASL connection
I1214 04:41:11.570439  2035 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I1214 04:41:11.570461  2040 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1214 04:41:11.570478  2035 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I1214 04:41:11.570752  2035 slave.cpp:539] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1214 04:41:11.570791  2035 slave.cpp:547] Agent attributes: [  ]
I1214 04:41:11.570801  2035 slave.cpp:552] Agent hostname: gru1.hw.ca1.mesosphere.com
I1214 04:41:11.571265  2035 state.cpp:57] Recovering state from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_7badJc/meta'
I1214 04:41:11.571367  2035 status_update_manager.cpp:203] Recovering status update manager
I1214 04:41:11.571449  2035 slave.cpp:5420] Finished recovery
I1214 04:41:11.571684  2035 slave.cpp:924] New master detected at master@192.99.40.208:37659
I1214 04:41:11.571702  2035 slave.cpp:983] Authenticating with master master@192.99.40.208:37659
I1214 04:41:11.571720  2035 slave.cpp:994] Using default CRAM-MD5 authenticatee
I1214 04:41:11.571751  2035 slave.cpp:956] Detecting new master
I1214 04:41:11.571807  2035 status_update_manager.cpp:177] Pausing sending status updates
I1214 04:41:11.571841  2035 authenticatee.cpp:121] Creating new client SASL connection
I1214 04:41:11.571909  2035 master.cpp:6748] Authenticating slave(912)@192.99.40.208:37659
I1214 04:41:11.571982  2035 authenticator.cpp:98] Creating new server SASL connection
I1214 04:41:11.572031  2035 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1214 04:41:11.572052  2035 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1214 04:41:11.572078  2035 authenticator.cpp:204] Received SASL authentication start
I1214 04:41:11.572108  2035 authenticator.cpp:326] Authentication requires more steps
I1214 04:41:11.572135  2035 authenticatee.cpp:259] Received SASL authentication step
I1214 04:41:11.572171  2035 authenticator.cpp:232] Received SASL authentication step
I1214 04:41:11.572201  2035 authenticator.cpp:318] Authentication success
I1214 04:41:11.572234  2035 authenticatee.cpp:299] Authentication success
I1214 04:41:11.572257  2035 master.cpp:6778] Successfully authenticated principal 'test-principal' at slave(912)@192.99.40.208:37659
I1214 04:41:11.572331  2035 slave.cpp:1078] Successfully authenticated with master master@192.99.40.208:37659
I1214 04:41:11.572430  2035 master.cpp:5161] Registering agent at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com) with id 87dd8179-dd7d-4270-ace2-ea771b57371c-S0
I1214 04:41:11.572541  2035 registrar.cpp:461] Applied 1 operations in 18957ns; attempting to update the registry
I1214 04:41:11.572929  2035 registrar.cpp:506] Successfully updated the registry in 363008ns
I1214 04:41:11.573122  2035 master.cpp:5232] Registered agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1214 04:41:11.573240  2035 hierarchical.cpp:490] Added agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 (gru1.hw.ca1.mesosphere.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I1214 04:41:11.573312  2035 slave.cpp:1124] Registered with master master@192.99.40.208:37659; given agent ID 87dd8179-dd7d-4270-ace2-ea771b57371c-S0
I1214 04:41:11.573545  2035 slave.cpp:1184] Forwarding total oversubscribed resources {}
I1214 04:41:11.573599  2035 status_update_manager.cpp:184] Resuming sending status updates
I1214 04:41:11.573631  2035 master.cpp:5633] Received update of agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com) with total oversubscribed resources {}
I1214 04:41:11.573696  2035 hierarchical.cpp:560] Agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 (gru1.hw.ca1.mesosphere.com) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {})
I1214 04:41:11.570480  2040 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1214 04:41:11.573894  2040 authenticator.cpp:204] Received SASL authentication start
I1214 04:41:11.573921  2040 authenticator.cpp:326] Authentication requires more steps
I1214 04:41:11.573951  2040 authenticatee.cpp:259] Received SASL authentication step
I1214 04:41:11.573988  2040 authenticator.cpp:232] Received SASL authentication step
I1214 04:41:11.574015  2040 authenticator.cpp:318] Authentication success
I1214 04:41:11.574054  2040 authenticatee.cpp:299] Authentication success
I1214 04:41:11.574079  2040 master.cpp:6778] Successfully authenticated principal 'test-principal' at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.574154  2040 sched.cpp:508] Successfully authenticated with master master@192.99.40.208:37659
I1214 04:41:11.574247  2040 master.cpp:2633] Received SUBSCRIBE call for framework 'default' at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.574265  2040 master.cpp:2081] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1214 04:41:11.574359  2040 master.cpp:2709] Subscribing framework default with checkpointing disabled and capabilities [  ]
I1214 04:41:11.574496  2040 hierarchical.cpp:276] Added framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.574750  2040 sched.cpp:749] Framework registered with 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.574884  2040 master.cpp:6577] Sending 1 offers to framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.575361  2040 master.cpp:3588] Processing ACCEPT call for offers: [ 87dd8179-dd7d-4270-ace2-ea771b57371c-O0 ] on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com) for framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.575392  2040 master.cpp:3175] Authorizing framework principal 'test-principal' to launch task 0
W1214 04:41:11.575858  2040 validation.cpp:1001] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W1214 04:41:11.575880  2040 validation.cpp:1013] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I1214 04:41:11.575949  2040 master.cpp:8501] Adding task 0 with resources cpus(*):1; mem(*):512 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.575989  2040 master.cpp:4240] Launching task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659 with resources cpus(*):1; mem(*):512 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.576154  2040 slave.cpp:1556] Got assigned task '0' for framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.576323  2040 slave.cpp:1718] Launching task '0' for framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.576510  2040 paths.cpp:530] Trying to chown '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_7badJc/slaves/87dd8179-dd7d-4270-ace2-ea771b57371c-S0/frameworks/87dd8179-dd7d-4270-ace2-ea771b57371c-0000/executors/default/runs/d6293832-3a4c-4731-b4de-da91f64c1c09' to user 'bbannier'
I1214 04:41:11.586915  2040 slave.cpp:6347] Launching executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 with resources {} in work directory '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_7badJc/slaves/87dd8179-dd7d-4270-ace2-ea771b57371c-S0/frameworks/87dd8179-dd7d-4270-ace2-ea771b57371c-0000/executors/default/runs/d6293832-3a4c-4731-b4de-da91f64c1c09'
I1214 04:41:11.587187  2040 slave.cpp:2040] Queued task '0' for executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.588081  2034 exec.cpp:162] Version: 1.2.0
I1214 04:41:11.588315  2035 slave.cpp:3314] Got registration for executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 from executor(912)@192.99.40.208:37659
I1214 04:41:11.588631  2046 exec.cpp:237] Executor registered on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0
I1214 04:41:11.588687  2035 slave.cpp:2256] Sending queued task '0' to executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 at executor(912)@192.99.40.208:37659
I1214 04:41:11.588961  2034 slave.cpp:3749] Handling status update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 from executor(912)@192.99.40.208:37659
I1214 04:41:11.589154  2044 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.589452  2044 slave.cpp:4190] Forwarding the update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 to master@192.99.40.208:37659
I1214 04:41:11.589516  2044 slave.cpp:4100] Sending acknowledgement for status update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 to executor(912)@192.99.40.208:37659
I1214 04:41:11.589596  2044 master.cpp:5769] Status update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 from agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.589625  2044 master.cpp:5831] Forwarding status update TASK_RUNNING (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.589680  2044 master.cpp:7867] Updating the state of task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1214 04:41:11.589999  2034 master.cpp:4877] Processing ACKNOWLEDGE call c9738162-8aa4-40f7-9be8-ec1d4877a94c for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0
I1214 04:41:11.590206  2045 status_update_manager.cpp:395] Received status update acknowledgement (UUID: c9738162-8aa4-40f7-9be8-ec1d4877a94c) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.591419  2043 slave.cpp:3749] Handling status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 from executor(912)@192.99.40.208:37659
I1214 04:41:11.591619  2043 status_update_manager.cpp:323] Received status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.591711  2043 slave.cpp:4190] Forwarding the update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 to master@192.99.40.208:37659
I1214 04:41:11.591760  2043 slave.cpp:4100] Sending acknowledgement for status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 to executor(912)@192.99.40.208:37659
I1214 04:41:11.592257  2043 slave.cpp:924] New master detected at master@192.99.40.208:37659
I1214 04:41:11.592280  2043 slave.cpp:983] Authenticating with master master@192.99.40.208:37659
I1214 04:41:11.592298  2043 slave.cpp:994] Using default CRAM-MD5 authenticatee
I1214 04:41:11.592313  2039 status_update_manager.cpp:177] Pausing sending status updates
I1214 04:41:11.592341  2043 slave.cpp:956] Detecting new master
I1214 04:41:11.592363  2039 authenticatee.cpp:121] Creating new client SASL connection
I1214 04:41:11.592383  2043 slave.cpp:4318] Got exited event for executor(912)@192.99.40.208:37659
I1214 04:41:11.592438  2039 master.cpp:6748] Authenticating slave(912)@192.99.40.208:37659
I1214 04:41:11.592550  2039 authenticator.cpp:98] Creating new server SASL connection
I1214 04:41:11.592614  2039 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1214 04:41:11.592635  2039 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1214 04:41:11.592672  2039 authenticator.cpp:204] Received SASL authentication start
I1214 04:41:11.592707  2039 authenticator.cpp:326] Authentication requires more steps
I1214 04:41:11.592741  2039 authenticatee.cpp:259] Received SASL authentication step
I1214 04:41:11.592779  2039 authenticator.cpp:232] Received SASL authentication step
I1214 04:41:11.592819  2039 authenticator.cpp:318] Authentication success
I1214 04:41:11.592850  2039 authenticatee.cpp:299] Authentication success
I1214 04:41:11.592870  2039 master.cpp:6778] Successfully authenticated principal 'test-principal' at slave(912)@192.99.40.208:37659
I1214 04:41:11.592921  2039 slave.cpp:1078] Successfully authenticated with master master@192.99.40.208:37659
I1214 04:41:11.593102  2039 master.cpp:5311] Re-registering agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.593189  2039 master.cpp:5572] Sending updated checkpointed resources {} to agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.593250  2039 slave.cpp:1226] Re-registered with master master@192.99.40.208:37659
I1214 04:41:11.593283  2039 slave.cpp:1262] Forwarding total oversubscribed resources {}
I1214 04:41:11.593329  2039 status_update_manager.cpp:184] Resuming sending status updates
W1214 04:41:11.593340  2039 status_update_manager.cpp:191] Resending status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.593410  2039 master.cpp:5633] Received update of agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com) with total oversubscribed resources {}
I1214 04:41:11.593451  2039 slave.cpp:4190] Forwarding the update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 to master@192.99.40.208:37659
I1214 04:41:11.593497  2039 hierarchical.cpp:560] Agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 (gru1.hw.ca1.mesosphere.com) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):512)
I1214 04:41:11.593605  2039 master.cpp:5769] Status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 from agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.593619  2039 master.cpp:5831] Forwarding status update TASK_FINISHED (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.593657  2039 master.cpp:7867] Updating the state of task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1214 04:41:11.593978  2041 master.cpp:4877] Processing ACKNOWLEDGE call 79f94437-6066-412e-9de6-6d9a1f256539 for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0
I1214 04:41:11.594013  2041 master.cpp:7963] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.594048  2005 sched.cpp:2008] Asked to stop the driver
I1214 04:41:11.594158  2048 sched.cpp:1193] Stopping framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.594192  2041 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 79f94437-6066-412e-9de6-6d9a1f256539) for task 0 of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.594251  2048 master.cpp:7287] Processing TEARDOWN call for framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.594272  2048 master.cpp:7299] Removing framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 (default) at scheduler-fa6ed654-9991-4bce-ab02-95d8530f96b3@192.99.40.208:37659
I1214 04:41:11.594336  2048 master.cpp:7992] Removing executor 'default' with resources {} of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
I1214 04:41:11.594383  2041 hierarchical.cpp:391] Deactivated framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.594450  2041 hierarchical.cpp:342] Removed framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.594570  2042 slave.cpp:2609] Shutting down framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
I1214 04:41:11.594593  2042 slave.cpp:4999] Shutting down executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 at executor(912)@192.99.40.208:37659
I1214 04:41:11.594758  2040 slave.cpp:4681] Executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 exited with status 0
I1214 04:41:11.594861  2040 slave.cpp:4785] Cleaning up executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 at executor(912)@192.99.40.208:37659
W1214 04:41:11.594920  2041 master.cpp:5887] Ignoring unknown exited executor 'default' of framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000 on agent 87dd8179-dd7d-4270-ace2-ea771b57371c-S0 at slave(912)@192.99.40.208:37659 (gru1.hw.ca1.mesosphere.com)
../../src/tests/master_slave_reconciliation_tests.cpp:145: Failure
Actual function call count doesn't match EXPECT_CALL(sched, executorLost(&driver, createExecutorInfo("default", "exit 1").executor_id(), _, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
*** Aborted at 1481708471 (unix time) try "date -d @1481708471" if you are using GNU date ***
I1214 04:41:11.595078  2040 slave.cpp:4873] Cleaning up framework 87dd8179-dd7d-4270-ace2-ea771b57371c-0000
PC: @          0x1d5c445 testing::UnitTest::AddTestPartResult()
*** SIGSEGV (@0x0) received by PID 2005 (TID 0x7f04125ff8c0) from PID 0; stack trace: ***
    @     0x7f040d5c95c0 (unknown)
    @          0x1d5c445 testing::UnitTest::AddTestPartResult()
    @          0x1d5c0af testing::internal::AssertHelper::operator=()
    @          0x1d8b61f testing::internal::GoogleTestFailureReporter::ReportFailure()
    @          0x1d80511 testing::internal::UntypedFunctionMockerBase::VerifyAndClearExpectationsLocked()
    @          0x1136031 testing::internal::FunctionMockerBase<>::~FunctionMockerBase()
    @          0x112e023 mesos::internal::tests::MockScheduler::~MockScheduler()
    @           0xf66780 mesos::internal::tests::MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_Test::TestBody()
    @          0x1d84a46 testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x1d6450d testing::Test::Run()
    @          0x1d65520 testing::TestInfo::Run()
    @          0x1d65c23 testing::TestCase::Run()
    @          0x1d6d8b9 testing::internal::UnitTestImpl::RunAllTests()
    @          0x1d8539f testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x1d6d55f testing::UnitTest::Run()
    @           0xd5d8bb main
    @     0x7f040c348401 __libc_start_main
    @           0x51a81a _start

Attachments

Issue Links

is related to

MESOS-3422 MasterSlaveReconciliationTest.ReconcileLostTask test is flaky

Resolved

Activity

People

Assignee:: Unassigned

Reporter:: Benjamin Bannier

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 14/Dec/16 09:53

Updated:: 24/Jan/19 20:20

Resolved:: 24/Jan/19 20:20