mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Michael Park (JIRA)" <j...@apache.org>
Subject [jira] [Created] (MESOS-6990) `PartitionTest.TaskCompletedOnPartitionedAgent` is flaky
Date Wed, 25 Jan 2017 19:35:26 GMT
Michael Park created MESOS-6990:
-----------------------------------

             Summary: `PartitionTest.TaskCompletedOnPartitionedAgent` is flaky
                 Key: MESOS-6990
                 URL: https://issues.apache.org/jira/browse/MESOS-6990
             Project: Mesos
          Issue Type: Bug
          Components: tests
            Reporter: Michael Park


Observed in the ASF Jenkins CI:

{noformat}
/mesos/src/tests/partition_tests.cpp:2055: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
{noformat}

Full log for the test:

{noformat}
[ RUN      ] PartitionTest.TaskCompletedOnPartitionedAgent
I0125 15:16:42.170163 25314 cluster.cpp:160] Creating default 'local' authorizer
I0125 15:16:42.171134 25325 master.cpp:383] Master 6361cb74-ebfe-43e5-9927-652201a9677a (9cdefe4ff6bc) started on 172.17.0.3:57726
I0125 15:16:42.171160 25325 master.cpp:385] 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/GAnqYR/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" --max_unreachable_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="/usr/local/share/mesos/webui" --work_dir="/tmp/GAnqYR/master" --zk_session_timeout="10secs"
I0125 15:16:42.171417 25325 master.cpp:435] Master only allowing authenticated frameworks to register
I0125 15:16:42.171427 25325 master.cpp:449] Master only allowing authenticated agents to register
I0125 15:16:42.171433 25325 master.cpp:462] Master only allowing authenticated HTTP frameworks to register
I0125 15:16:42.171439 25325 credentials.hpp:37] Loading credentials for authentication from '/tmp/GAnqYR/credentials'
I0125 15:16:42.171571 25325 master.cpp:507] Using default 'crammd5' authenticator
I0125 15:16:42.171614 25325 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0125 15:16:42.171658 25325 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0125 15:16:42.171684 25325 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0125 15:16:42.171710 25325 master.cpp:587] Authorization enabled
I0125 15:16:42.172552 25325 hierarchical.cpp:151] Initialized hierarchical allocator process
I0125 15:16:42.172575 25325 whitelist_watcher.cpp:77] No whitelist given
I0125 15:16:42.173259 25325 master.cpp:2121] Elected as the leading master!
I0125 15:16:42.173274 25325 master.cpp:1643] Recovering from registrar
I0125 15:16:42.173328 25325 registrar.cpp:329] Recovering registrar
I0125 15:16:42.173552 25325 registrar.cpp:362] Successfully fetched the registry (0B) in 0ns
I0125 15:16:42.173588 25325 registrar.cpp:461] Applied 1 operations in 8907ns; attempting to update the registry
I0125 15:16:42.173854 25325 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:42.173898 25325 registrar.cpp:392] Successfully recovered registrar
I0125 15:16:42.174008 25325 master.cpp:1759] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0125 15:16:42.174048 25325 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
I0125 15:16:42.175926 25314 cluster.cpp:446] Creating default 'local' authorizer
I0125 15:16:42.176554 25321 slave.cpp:209] Mesos agent started on (93)@172.17.0.3:57726
I0125 15:16:42.176578 25321 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/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/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/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/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/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/http_credentials" --http_heartbeat_interval="30secs" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/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/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc" --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/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2"
I0125 15:16:42.176937 25321 credentials.hpp:86] Loading credential for authentication from '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/credential'
I0125 15:16:42.177004 25321 slave.cpp:352] Agent using credential for: test-principal
I0125 15:16:42.177014 25321 credentials.hpp:37] Loading credentials for authentication from '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/http_credentials'
I0125 15:16:42.177088 25321 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0125 15:16:42.177129 25321 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0125 15:16:42.177423 25321 slave.cpp:539] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:42.177453 25321 slave.cpp:547] Agent attributes: [  ]
I0125 15:16:42.177458 25321 slave.cpp:552] Agent hostname: 9cdefe4ff6bc
I0125 15:16:42.177510 25328 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:42.177903 25327 state.cpp:60] Recovering state from '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/meta'
I0125 15:16:42.178035 25318 status_update_manager.cpp:203] Recovering status update manager
I0125 15:16:42.178190 25330 slave.cpp:5422] Finished recovery
I0125 15:16:42.178570 25330 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.178709 25330 slave.cpp:929] New master detected at master@172.17.0.3:57726
I0125 15:16:42.178733 25330 slave.cpp:964] Detecting new master
I0125 15:16:42.178745 25314 sched.cpp:232] Version: 1.2.0
I0125 15:16:42.178773 25330 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.178813 25323 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:42.178964 25323 sched.cpp:336] New master detected at master@172.17.0.3:57726
I0125 15:16:42.178993 25323 sched.cpp:407] Authenticating with master master@172.17.0.3:57726
I0125 15:16:42.179003 25323 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0125 15:16:42.179086 25323 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:42.179247 25323 master.cpp:7001] Authenticating scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.179306 25323 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(217)@172.17.0.3:57726
I0125 15:16:42.179375 25323 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:42.179497 25323 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:42.179522 25323 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:42.179559 25323 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:42.179605 25323 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:42.179641 25323 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:42.179685 25323 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:42.179704 25323 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:42.179715 25323 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:42.179730 25323 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:42.179744 25323 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:42.179754 25323 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.179762 25323 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.179778 25323 authenticator.cpp:318] Authentication success
I0125 15:16:42.179831 25323 authenticatee.cpp:299] Authentication success
I0125 15:16:42.179862 25323 master.cpp:7031] Successfully authenticated principal 'test-principal' at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.179890 25323 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(217)@172.17.0.3:57726
I0125 15:16:42.179970 25323 sched.cpp:513] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:42.179983 25323 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.3:57726
I0125 15:16:42.180016 25323 sched.cpp:869] Will retry registration in 1.440407408secs if necessary
I0125 15:16:42.180097 25323 master.cpp:2734] Received SUBSCRIBE call for framework 'default' at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.180112 25323 master.cpp:2157] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0125 15:16:42.180222 25323 master.cpp:2810] Subscribing framework default with checkpointing disabled and capabilities [  ]
I0125 15:16:42.180383 25323 hierarchical.cpp:271] Added framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.180404 25323 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.180414 25323 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.180426 25323 hierarchical.cpp:1279] Performed allocation for 0 agents in 33111ns
I0125 15:16:42.180522 25323 sched.cpp:759] Framework registered with 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.180546 25323 sched.cpp:773] Scheduler::registered took 15260ns
I0125 15:16:42.180716 25321 slave.cpp:991] Authenticating with master master@172.17.0.3:57726
I0125 15:16:42.180738 25321 slave.cpp:1002] Using default CRAM-MD5 authenticatee
I0125 15:16:42.180799 25321 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:42.180920 25321 master.cpp:7001] Authenticating slave(93)@172.17.0.3:57726
I0125 15:16:42.180964 25321 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(218)@172.17.0.3:57726
I0125 15:16:42.181020 25321 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:42.181123 25321 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:42.181144 25321 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:42.181177 25321 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:42.181210 25321 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:42.181243 25321 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:42.181291 25321 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:42.181308 25321 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:42.181319 25321 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:42.181329 25321 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:42.181341 25321 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:42.181351 25321 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.181360 25321 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.181375 25321 authenticator.cpp:318] Authentication success
I0125 15:16:42.181414 25321 authenticatee.cpp:299] Authentication success
I0125 15:16:42.181443 25321 master.cpp:7031] Successfully authenticated principal 'test-principal' at slave(93)@172.17.0.3:57726
I0125 15:16:42.181471 25321 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(218)@172.17.0.3:57726
I0125 15:16:42.181548 25321 slave.cpp:1086] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:42.181596 25321 slave.cpp:1508] Will retry registration in 19.250331ms if necessary
I0125 15:16:42.181694 25321 master.cpp:5299] Registering agent at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) with id 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.181819 25321 registrar.cpp:461] Applied 1 operations in 19275ns; attempting to update the registry
I0125 15:16:42.182193 25321 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:42.182413 25321 master.cpp:5370] Registered agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:42.182545 25321 hierarchical.cpp:478] Added agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0125 15:16:42.182763 25321 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.182782 25321 hierarchical.cpp:1302] Performed allocation for agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 218565ns
I0125 15:16:42.182821 25321 slave.cpp:1132] Registered with master master@172.17.0.3:57726; given agent ID 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.182834 25321 fetcher.cpp:90] Clearing fetcher cache
I0125 15:16:42.183110 25321 slave.cpp:1160] Checkpointing SlaveInfo to '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/meta/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/slave.info'
I0125 15:16:42.183348 25321 slave.cpp:1198] Forwarding total oversubscribed resources {}
I0125 15:16:42.183396 25321 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.183537 25321 master.cpp:6830] Sending 1 offers to framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.183598 25321 master.cpp:5863] Received update of agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) with total oversubscribed resources {}
I0125 15:16:42.183658 25321 status_update_manager.cpp:184] Resuming sending status updates
I0125 15:16:42.183769 25321 sched.cpp:933] Scheduler::resourceOffers took 34059ns
I0125 15:16:42.183820 25321 hierarchical.cpp:548] Agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0125 15:16:42.183866 25321 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.183876 25321 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.183886 25321 hierarchical.cpp:1302] Performed allocation for agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 40916ns
I0125 15:16:42.184298 25325 master.cpp:3728] Processing ACCEPT call for offers: [ 6361cb74-ebfe-43e5-9927-652201a9677a-O0 ] on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.184329 25325 master.cpp:3316] Authorizing framework principal 'test-principal' to launch task 1
W0125 15:16:42.184788 25325 validation.cpp:1018] Executor 'default' for task '1' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0125 15:16:42.184808 25325 validation.cpp:1030] Executor 'default' for task '1' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0125 15:16:42.184877 25325 master.cpp:8882] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.184931 25325 master.cpp:4378] Launching task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.185075 25316 slave.cpp:1576] Got assigned task '1' for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.185384 25316 slave.cpp:1736] Launching task '1' for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.185916 25316 paths.cpp:547] Trying to chown '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a' to user 'mesos'
I0125 15:16:42.186097 25316 slave.cpp:6331] Launching executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 with resources {} in work directory '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a'
I0125 15:16:42.186307 25316 slave.cpp:2058] Queued task '1' for executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.187432 25316 exec.cpp:162] Version: 1.2.0
I0125 15:16:42.187597 25316 slave.cpp:882] Successfully attached file '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a'
I0125 15:16:42.187671 25316 exec.cpp:212] Executor started at: executor(35)@172.17.0.3:57726 with pid 25314
I0125 15:16:42.187741 25316 slave.cpp:3325] Got registration for executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from executor(35)@172.17.0.3:57726
I0125 15:16:42.187927 25316 exec.cpp:237] Executor registered on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.187952 25316 exec.cpp:249] Executor::registered took 15906ns
I0125 15:16:42.188055 25316 slave.cpp:2271] Sending queued task '1' to executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at executor(35)@172.17.0.3:57726
I0125 15:16:42.188148 25316 exec.cpp:320] Executor asked to run task '1'
I0125 15:16:42.188211 25316 exec.cpp:329] Executor::launchTask took 55213ns
I0125 15:16:42.188321 25324 exec.cpp:546] Executor sending status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.188499 25319 slave.cpp:3756] Handling status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from executor(35)@172.17.0.3:57726
I0125 15:16:42.188787 25319 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.188809 25319 status_update_manager.cpp:500] Creating StatusUpdate stream for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.188954 25319 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 to the agent
I0125 15:16:42.189065 25319 slave.cpp:4196] Forwarding the update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 to master@172.17.0.3:57726
I0125 15:16:42.189131 25319 slave.cpp:4090] Status update manager successfully handled status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.189152 25319 slave.cpp:4106] Sending acknowledgement for status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 to executor(35)@172.17.0.3:57726
I0125 15:16:42.189227 25319 master.cpp:6008] Status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.189252 25319 master.cpp:6076] Forwarding status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.189299 25319 master.cpp:8138] Updating the state of task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:16:42.189342 25319 exec.cpp:369] Executor received status update acknowledgement 18117425-d755-4536-b9e6-5749a3260021 for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.189419 25319 sched.cpp:1041] Scheduler::statusUpdate took 16303ns
I0125 15:16:42.189539 25319 master.cpp:5015] Processing ACKNOWLEDGE call 18117425-d755-4536-b9e6-5749a3260021 for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.189623 25319 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.189699 25319 slave.cpp:3045] Status update manager successfully handled status update acknowledgement (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.189985 25319 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.190217 25319 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.190347 25319 hierarchical.cpp:1279] Performed allocation for 1 agents in 391006ns
I0125 15:16:42.190134 25330 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.190619 25319 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.190814 25319 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.191201 25330 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.191373 25330 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.191480 25330 hierarchical.cpp:1279] Performed allocation for 1 agents in 305591ns
I0125 15:16:42.191308 25326 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.191682 25326 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.191872 25326 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.192205 25317 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.192353 25317 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.192467 25317 hierarchical.cpp:1279] Performed allocation for 1 agents in 303235ns
I0125 15:16:42.192337 25326 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.192814 25326 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.193055 25320 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.193411 25328 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.193467 25328 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.193518 25328 slave.cpp:5189] Current disk usage 10.11%. Max allowed age: 5.592125848493229days
I0125 15:16:42.193629 25328 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.193706 25326 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.193720 25326 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.193733 25326 hierarchical.cpp:1279] Performed allocation for 1 agents in 54039ns
I0125 15:16:42.193912 25320 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.193925 25320 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.193939 25320 hierarchical.cpp:1279] Performed allocation for 1 agents in 53293ns
I0125 15:16:42.194070 25330 master.cpp:6236] Marking agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) unreachable: health check timed out
I0125 15:16:42.194226 25330 registrar.cpp:461] Applied 1 operations in 36755ns; attempting to update the registry
I0125 15:16:42.194615 25330 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:42.194725 25330 master.cpp:6284] Marked agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) unreachable: health check timed out
I0125 15:16:42.194778 25330 master.cpp:8138] Updating the state of task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
I0125 15:16:42.194928 25330 master.cpp:8232] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.195008 25330 master.cpp:6071] Sending status update TASK_LOST for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 'Agent 9cdefe4ff6bc is unreachable: health check timed out'
I0125 15:16:42.195078 25330 master.cpp:8261] Removing executor 'default' with resources {} of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.195186 25330 master.cpp:2038] Notifying framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 of lost agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 (9cdefe4ff6bc)
I0125 15:16:42.195349 25330 hierarchical.cpp:510] Removed agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.195626 25330 sched.cpp:1041] Scheduler::statusUpdate took 29701ns
I0125 15:16:42.195675 25330 sched.cpp:1103] Lost agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0
I0125 15:16:42.195703 25330 sched.cpp:1114] Scheduler::slaveLost took 19580ns
I0125 15:16:42.195803 25320 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:42.195927 25320 slave.cpp:4286] Received ping from slave-observer(93)@172.17.0.3:57726
I0125 15:16:42.196137 25320 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:42.196570 25325 slave.cpp:922] Lost leading master
I0125 15:16:42.196722 25321 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:42.196892 25325 slave.cpp:964] Detecting new master
I0125 15:16:42.197209 25325 slave.cpp:929] New master detected at master@172.17.0.3:57726
I0125 15:16:42.197353 25325 slave.cpp:964] Detecting new master
I0125 15:16:42.197535 25325 slave.cpp:991] Authenticating with master master@172.17.0.3:57726
I0125 15:16:42.197669 25325 slave.cpp:1002] Using default CRAM-MD5 authenticatee
I0125 15:16:42.197832 25325 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:42.198011 25325 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:42.198261 25325 master.cpp:7001] Authenticating slave(93)@172.17.0.3:57726
I0125 15:16:42.198429 25325 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(219)@172.17.0.3:57726
I0125 15:16:42.198621 25325 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:42.198868 25325 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:42.199010 25325 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:42.199162 25325 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:42.199326 25325 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:42.199478 25325 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:42.199645 25325 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:42.199780 25325 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:42.199906 25325 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:42.200032 25325 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:42.200166 25325 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:42.200287 25325 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.200405 25325 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:42.200536 25325 authenticator.cpp:318] Authentication success
I0125 15:16:42.200724 25325 authenticatee.cpp:299] Authentication success
I0125 15:16:42.200877 25325 master.cpp:7031] Successfully authenticated principal 'test-principal' at slave(93)@172.17.0.3:57726
I0125 15:16:42.201025 25325 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(219)@172.17.0.3:57726
I0125 15:16:42.201233 25325 slave.cpp:1086] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:42.201454 25325 slave.cpp:1508] Will retry registration in 8.042063ms if necessary
I0125 15:16:42.201716 25325 master.cpp:5522] Re-registering agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.202100 25325 registrar.cpp:461] Applied 1 operations in 25969ns; attempting to update the registry
I0125 15:16:42.202669 25325 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:42.203146 25325 master.cpp:5694] Re-registered agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:42.203568 25325 master.cpp:5714] Shutting down framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at re-registered agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) because the framework is not partition-aware
I0125 15:16:42.203729 25325 master.cpp:5802] Sending updated checkpointed resources {} to agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:42.203348 25330 hierarchical.cpp:478] Added agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0125 15:16:42.204207 25330 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.204551 25330 hierarchical.cpp:1302] Performed allocation for agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 556594ns
I0125 15:16:42.204411 25326 master.cpp:6830] Sending 1 offers to framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:42.204952 25326 sched.cpp:933] Scheduler::resourceOffers took 19578ns
I0125 15:16:42.203431 25327 slave.cpp:1240] Re-registered with master master@172.17.0.3:57726
I0125 15:16:42.205257 25327 slave.cpp:1277] Forwarding total oversubscribed resources {}
I0125 15:16:42.205466 25327 slave.cpp:4286] Received ping from slave-observer(94)@172.17.0.3:57726
I0125 15:16:42.205631 25327 slave.cpp:2598] Asked to shut down framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 by master@172.17.0.3:57726
I0125 15:16:42.205770 25327 slave.cpp:2623] Shutting down framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.205899 25327 slave.cpp:5005] Shutting down executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at executor(35)@172.17.0.3:57726
W0125 15:16:42.206079 25327 slave.cpp:2763] Ignoring updating pid for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 because it is terminating
I0125 15:16:42.205346 25318 status_update_manager.cpp:184] Resuming sending status updates
I0125 15:16:42.206244 25319 master.cpp:5863] Received update of agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) with total oversubscribed resources {}
I0125 15:16:42.206284 25327 slave.cpp:2830] Ignoring new checkpointed resources identical to the current version: {}
I0125 15:16:42.196985 25316 exec.cpp:546] Executor sending status update TASK_FINISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.206491 25329 hierarchical.cpp:548] Agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0125 15:16:42.206758 25329 hierarchical.cpp:1677] No allocations performed
I0125 15:16:42.206795 25329 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:42.206827 25316 exec.cpp:410] Executor asked to shutdown
I0125 15:16:42.207140 25316 exec.cpp:425] Executor::shutdown took 24713ns
I0125 15:16:42.206925 25328 slave.cpp:3756] Handling status update TASK_FINISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from executor(35)@172.17.0.3:57726
W0125 15:16:42.207347 25328 slave.cpp:3825] Ignoring status update TASK_FINISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 for terminating framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:42.207540 25316 slave.cpp:4328] Got exited event for executor(35)@172.17.0.3:57726
I0125 15:16:42.206830 25329 hierarchical.cpp:1302] Performed allocation for agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 104733ns
/mesos/src/tests/partition_tests.cpp:2064: Failure
Failed to wait 15secs for finishedStatus
I0125 15:16:57.211380 25326 master.cpp:1378] Framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 disconnected
I0125 15:16:57.211426 25326 master.cpp:3078] Deactivating framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
/mesos/src/tests/partition_tests.cpp:2055: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
I0125 15:16:57.211555 25327 hierarchical.cpp:386] Deactivated framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.211673 25326 master.cpp:3055] Disconnecting framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:57.211701 25326 master.cpp:1393] Giving framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 0ns to failover
I0125 15:16:57.211863 25327 hierarchical.cpp:1011] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 from framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.211979 25326 master.cpp:6682] Framework failover timeout, removing framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:57.212059 25326 master.cpp:7555] Removing framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726
I0125 15:16:57.212182 25326 master.cpp:8261] Removing executor 'default' with resources {} of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.212309 25315 slave.cpp:2598] Asked to shut down framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 by master@172.17.0.3:57726
W0125 15:16:57.212338 25315 slave.cpp:2619] Ignoring shutdown framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 because it is terminating
I0125 15:16:57.212626 25328 hierarchical.cpp:337] Removed framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.213990 25326 slave.cpp:4691] Executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 exited with status 0
I0125 15:16:57.214105 25326 slave.cpp:4791] Cleaning up executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at executor(35)@172.17.0.3:57726
W0125 15:16:57.214220 25327 master.cpp:6132] Ignoring unknown exited executor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.214432 25318 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a' for gc 1.00002452166984weeks in the future
I0125 15:16:57.214548 25326 slave.cpp:4879] Cleaning up framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.214648 25319 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/default' for gc 1.00002452166984weeks in the future
I0125 15:16:57.214687 25319 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000' for gc 1.00002452166984weeks in the future
I0125 15:16:57.214817 25329 status_update_manager.cpp:285] Closing status update streams for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.214866 25329 status_update_manager.cpp:531] Cleaning up status update stream for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000
I0125 15:16:57.215348 25314 slave.cpp:801] Agent terminating
I0125 15:16:57.215633 25328 master.cpp:1261] Agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) disconnected
I0125 15:16:57.215654 25328 master.cpp:3115] Disconnecting agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.215690 25328 master.cpp:3134] Deactivating agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.215837 25329 hierarchical.cpp:577] Agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 deactivated
I0125 15:16:57.217043 25314 master.cpp:1100] Master terminating
I0125 15:16:57.217226 25320 hierarchical.cpp:510] Removed agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0
[  FAILED  ] PartitionTest.TaskCompletedOnPartitionedAgent (15049 ms)
[ RUN      ] PartitionTest.PartitionAwareTaskCompletedOnPartitionedAgent
I0125 15:16:57.221556 25314 cluster.cpp:160] Creating default 'local' authorizer
I0125 15:16:57.222678 25323 master.cpp:383] Master 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3 (9cdefe4ff6bc) started on 172.17.0.3:57726
I0125 15:16:57.222707 25323 master.cpp:385] 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/h7cPEl/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" --max_unreachable_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="/usr/local/share/mesos/webui" --work_dir="/tmp/h7cPEl/master" --zk_session_timeout="10secs"
I0125 15:16:57.222909 25323 master.cpp:435] Master only allowing authenticated frameworks to register
I0125 15:16:57.222921 25323 master.cpp:449] Master only allowing authenticated agents to register
I0125 15:16:57.222930 25323 master.cpp:462] Master only allowing authenticated HTTP frameworks to register
I0125 15:16:57.222962 25323 credentials.hpp:37] Loading credentials for authentication from '/tmp/h7cPEl/credentials'
I0125 15:16:57.223172 25323 master.cpp:507] Using default 'crammd5' authenticator
I0125 15:16:57.223227 25323 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0125 15:16:57.223306 25323 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0125 15:16:57.223387 25323 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0125 15:16:57.223441 25323 master.cpp:587] Authorization enabled
I0125 15:16:57.223608 25318 hierarchical.cpp:151] Initialized hierarchical allocator process
I0125 15:16:57.223614 25317 whitelist_watcher.cpp:77] No whitelist given
I0125 15:16:57.224509 25323 master.cpp:2121] Elected as the leading master!
I0125 15:16:57.224520 25323 master.cpp:1643] Recovering from registrar
I0125 15:16:57.224572 25323 registrar.cpp:329] Recovering registrar
I0125 15:16:57.224820 25323 registrar.cpp:362] Successfully fetched the registry (0B) in 0ns
I0125 15:16:57.224876 25323 registrar.cpp:461] Applied 1 operations in 28166ns; attempting to update the registry
I0125 15:16:57.225240 25315 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:57.225291 25315 registrar.cpp:392] Successfully recovered registrar
I0125 15:16:57.225442 25327 master.cpp:1759] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0125 15:16:57.225457 25315 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
I0125 15:16:57.227869 25314 cluster.cpp:446] Creating default 'local' authorizer
I0125 15:16:57.228396 25329 slave.cpp:209] Mesos agent started on (94)@172.17.0.3:57726
I0125 15:16:57.228420 25329 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/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/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/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/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/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/http_credentials" --http_heartbeat_interval="30secs" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/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/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX" --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/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9"
I0125 15:16:57.228858 25329 credentials.hpp:86] Loading credential for authentication from '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/credential'
I0125 15:16:57.229053 25329 slave.cpp:352] Agent using credential for: test-principal
I0125 15:16:57.229068 25329 credentials.hpp:37] Loading credentials for authentication from '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/http_credentials'
I0125 15:16:57.229094 25314 sched.cpp:232] Version: 1.2.0
I0125 15:16:57.229192 25327 sched.cpp:336] New master detected at master@172.17.0.3:57726
I0125 15:16:57.229267 25327 sched.cpp:407] Authenticating with master master@172.17.0.3:57726
I0125 15:16:57.229300 25327 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0125 15:16:57.229444 25323 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:57.229449 25329 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0125 15:16:57.229508 25329 http.cpp:922] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0125 15:16:57.229660 25323 master.cpp:7001] Authenticating scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.229821 25318 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(220)@172.17.0.3:57726
I0125 15:16:57.229969 25324 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:57.230144 25320 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:57.230175 25320 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:57.230168 25329 slave.cpp:539] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:57.230226 25329 slave.cpp:547] Agent attributes: [  ]
I0125 15:16:57.230270 25329 slave.cpp:552] Agent hostname: 9cdefe4ff6bc
I0125 15:16:57.230490 25324 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:57.230528 25320 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:57.230558 25324 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:57.230625 25324 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:57.230711 25315 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:57.230732 25315 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:57.230801 25315 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:57.230813 25315 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:57.230823 25315 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:57.230835 25315 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.230844 25315 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.230857 25315 authenticator.cpp:318] Authentication success
I0125 15:16:57.230922 25316 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(220)@172.17.0.3:57726
I0125 15:16:57.230903 25324 authenticatee.cpp:299] Authentication success
I0125 15:16:57.231065 25315 master.cpp:7031] Successfully authenticated principal 'test-principal' at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.231142 25316 sched.cpp:513] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:57.231158 25316 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.3:57726
I0125 15:16:57.231207 25316 sched.cpp:869] Will retry registration in 1.296809111secs if necessary
I0125 15:16:57.231364 25317 master.cpp:2734] Received SUBSCRIBE call for framework 'default' at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.231384 25317 master.cpp:2157] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0125 15:16:57.231644 25322 master.cpp:2810] Subscribing framework default with checkpointing disabled and capabilities [ PARTITION_AWARE ]
I0125 15:16:57.231863 25321 hierarchical.cpp:271] Added framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.231931 25315 sched.cpp:759] Framework registered with 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.232040 25329 state.cpp:60] Recovering state from '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/meta'
I0125 15:16:57.232167 25315 sched.cpp:773] Scheduler::registered took 29197ns
I0125 15:16:57.232100 25321 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.232317 25321 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.232334 25321 hierarchical.cpp:1279] Performed allocation for 0 agents in 249903ns
I0125 15:16:57.232494 25327 status_update_manager.cpp:203] Recovering status update manager
I0125 15:16:57.232693 25318 slave.cpp:5422] Finished recovery
I0125 15:16:57.233031 25318 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.233135 25318 slave.cpp:929] New master detected at master@172.17.0.3:57726
I0125 15:16:57.233150 25326 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:57.233340 25318 slave.cpp:964] Detecting new master
I0125 15:16:57.233417 25318 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.233471 25318 slave.cpp:991] Authenticating with master master@172.17.0.3:57726
I0125 15:16:57.233492 25318 slave.cpp:1002] Using default CRAM-MD5 authenticatee
I0125 15:16:57.233583 25318 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:57.233708 25318 master.cpp:7001] Authenticating slave(94)@172.17.0.3:57726
I0125 15:16:57.233757 25318 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(221)@172.17.0.3:57726
I0125 15:16:57.233835 25318 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:57.233952 25318 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:57.233974 25318 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:57.234019 25318 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:57.234061 25318 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:57.234109 25318 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:57.234153 25318 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:57.234171 25318 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:57.234185 25318 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:57.234197 25318 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:57.234211 25318 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:57.234222 25318 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.234230 25318 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.234244 25318 authenticator.cpp:318] Authentication success
I0125 15:16:57.234302 25318 authenticatee.cpp:299] Authentication success
I0125 15:16:57.234339 25318 master.cpp:7031] Successfully authenticated principal 'test-principal' at slave(94)@172.17.0.3:57726
I0125 15:16:57.234375 25318 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(221)@172.17.0.3:57726
I0125 15:16:57.234467 25318 slave.cpp:1086] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:57.234524 25318 slave.cpp:1508] Will retry registration in 2.172659ms if necessary
I0125 15:16:57.234637 25318 master.cpp:5299] Registering agent at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) with id 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.234752 25318 registrar.cpp:461] Applied 1 operations in 15921ns; attempting to update the registry
I0125 15:16:57.235049 25318 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:57.235239 25318 master.cpp:5370] Registered agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:57.235347 25318 hierarchical.cpp:478] Added agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0125 15:16:57.235530 25318 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.235553 25318 hierarchical.cpp:1302] Performed allocation for agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 191700ns
I0125 15:16:57.235595 25318 slave.cpp:1132] Registered with master master@172.17.0.3:57726; given agent ID 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.235612 25318 fetcher.cpp:90] Clearing fetcher cache
I0125 15:16:57.235841 25318 slave.cpp:1160] Checkpointing SlaveInfo to '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/meta/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/slave.info'
I0125 15:16:57.236044 25318 slave.cpp:1198] Forwarding total oversubscribed resources {}
I0125 15:16:57.236088 25318 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.236207 25318 master.cpp:6830] Sending 1 offers to framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.236268 25318 master.cpp:5863] Received update of agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) with total oversubscribed resources {}
I0125 15:16:57.236335 25318 status_update_manager.cpp:184] Resuming sending status updates
I0125 15:16:57.236446 25318 sched.cpp:933] Scheduler::resourceOffers took 24637ns
I0125 15:16:57.236496 25318 hierarchical.cpp:548] Agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0125 15:16:57.236543 25318 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.236559 25318 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.236572 25318 hierarchical.cpp:1302] Performed allocation for agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 52891ns
I0125 15:16:57.236970 25317 master.cpp:3728] Processing ACCEPT call for offers: [ 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-O0 ] on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.237028 25317 master.cpp:3316] Authorizing framework principal 'test-principal' to launch task 1
W0125 15:16:57.237627 25330 validation.cpp:1018] Executor 'default' for task '1' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0125 15:16:57.237646 25330 validation.cpp:1030] Executor 'default' for task '1' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0125 15:16:57.237792 25330 master.cpp:8882] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.237908 25330 master.cpp:4378] Launching task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.238124 25330 slave.cpp:1576] Got assigned task '1' for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.238366 25330 slave.cpp:1736] Launching task '1' for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.238796 25330 paths.cpp:547] Trying to chown '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452' to user 'mesos'
I0125 15:16:57.238963 25330 slave.cpp:6331] Launching executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 with resources {} in work directory '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452'
I0125 15:16:57.239156 25330 slave.cpp:2058] Queued task '1' for executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.239377 25320 slave.cpp:882] Successfully attached file '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452'
I0125 15:16:57.240170 25315 exec.cpp:162] Version: 1.2.0
I0125 15:16:57.240241 25317 exec.cpp:212] Executor started at: executor(36)@172.17.0.3:57726 with pid 25314
I0125 15:16:57.240470 25315 slave.cpp:3325] Got registration for executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from executor(36)@172.17.0.3:57726
I0125 15:16:57.240638 25318 exec.cpp:237] Executor registered on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.240746 25315 slave.cpp:2271] Sending queued task '1' to executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at executor(36)@172.17.0.3:57726
I0125 15:16:57.240878 25318 exec.cpp:249] Executor::registered took 105704ns
I0125 15:16:57.240934 25318 exec.cpp:320] Executor asked to run task '1'
I0125 15:16:57.241022 25318 exec.cpp:329] Executor::launchTask took 66708ns
I0125 15:16:57.241179 25317 exec.cpp:546] Executor sending status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.241276 25317 slave.cpp:3756] Handling status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from executor(36)@172.17.0.3:57726
I0125 15:16:57.241582 25328 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.241618 25328 status_update_manager.cpp:500] Creating StatusUpdate stream for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.241770 25328 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to the agent
I0125 15:16:57.241904 25330 slave.cpp:4196] Forwarding the update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to master@172.17.0.3:57726
I0125 15:16:57.241987 25330 slave.cpp:4090] Status update manager successfully handled status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.242010 25330 slave.cpp:4106] Sending acknowledgement for status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to executor(36)@172.17.0.3:57726
I0125 15:16:57.242105 25330 master.cpp:6008] Status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.242136 25330 master.cpp:6076] Forwarding status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.242192 25330 master.cpp:8138] Updating the state of task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0125 15:16:57.242241 25330 exec.cpp:369] Executor received status update acknowledgement cf817a99-c7fe-474f-adbf-397b19fc7ef5 for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.242321 25330 sched.cpp:1041] Scheduler::statusUpdate took 13730ns
I0125 15:16:57.242394 25330 master.cpp:5015] Processing ACKNOWLEDGE call cf817a99-c7fe-474f-adbf-397b19fc7ef5 for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.242480 25330 status_update_manager.cpp:395] Received status update acknowledgement (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.242555 25330 slave.cpp:3045] Status update manager successfully handled status update acknowledgement (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.242779 25317 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.242794 25317 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.242801 25330 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.242807 25317 hierarchical.cpp:1279] Performed allocation for 1 agents in 57725ns
I0125 15:16:57.243042 25330 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.243192 25330 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.243371 25320 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.243417 25318 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.243522 25318 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.243425 25320 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.243571 25318 hierarchical.cpp:1279] Performed allocation for 1 agents in 189209ns
I0125 15:16:57.243598 25320 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.243758 25322 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.243774 25322 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.243788 25322 hierarchical.cpp:1279] Performed allocation for 1 agents in 71161ns
I0125 15:16:57.243882 25318 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.244040 25318 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.244092 25318 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.244354 25320 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.244480 25320 slave.cpp:5189] Current disk usage 10.11%. Max allowed age: 5.592058203640729days
I0125 15:16:57.244604 25320 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.244709 25320 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.244755 25326 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.244787 25326 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.244817 25326 hierarchical.cpp:1279] Performed allocation for 1 agents in 250871ns
I0125 15:16:57.244976 25324 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.244992 25324 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.244982 25317 slave.cpp:5596] Querying resource estimator for oversubscribable resources
I0125 15:16:57.245005 25324 hierarchical.cpp:1279] Performed allocation for 1 agents in 60156ns
I0125 15:16:57.245086 25317 slave.cpp:4286] Received ping from slave-observer(95)@172.17.0.3:57726
I0125 15:16:57.245157 25317 slave.cpp:5610] Received oversubscribable resources {} from the resource estimator
I0125 15:16:57.245025 25321 master.cpp:6236] Marking agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) unreachable: health check timed out
I0125 15:16:57.245483 25317 registrar.cpp:461] Applied 1 operations in 25617ns; attempting to update the registry
I0125 15:16:57.245762 25322 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:57.245857 25317 master.cpp:6284] Marked agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) unreachable: health check timed out
I0125 15:16:57.246047 25320 hierarchical.cpp:510] Removed agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.246070 25317 master.cpp:8138] Updating the state of task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_UNREACHABLE, status update state: TASK_UNREACHABLE)
I0125 15:16:57.246251 25317 master.cpp:8232] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.246330 25317 master.cpp:6071] Sending status update TASK_UNREACHABLE for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 'Agent 9cdefe4ff6bc is unreachable: health check timed out'
I0125 15:16:57.246498 25317 master.cpp:8261] Removing executor 'default' with resources {} of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.246628 25327 sched.cpp:1041] Scheduler::statusUpdate took 31098ns
I0125 15:16:57.246682 25317 master.cpp:2038] Notifying framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 of lost agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc)
I0125 15:16:57.246773 25317 sched.cpp:1103] Lost agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.246807 25317 sched.cpp:1114] Scheduler::slaveLost took 23178ns
I0125 15:16:57.246893 25330 exec.cpp:546] Executor sending status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.247026 25324 slave.cpp:3756] Handling status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from executor(36)@172.17.0.3:57726
I0125 15:16:57.247184 25324 slave.cpp:922] Lost leading master
I0125 15:16:57.247201 25324 slave.cpp:964] Detecting new master
I0125 15:16:57.247205 25315 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:57.247407 25315 status_update_manager.cpp:177] Pausing sending status updates
I0125 15:16:57.247414 25325 slave.cpp:929] New master detected at master@172.17.0.3:57726
I0125 15:16:57.247458 25325 slave.cpp:964] Detecting new master
I0125 15:16:57.247612 25325 slave.cpp:991] Authenticating with master master@172.17.0.3:57726
I0125 15:16:57.247632 25325 slave.cpp:1002] Using default CRAM-MD5 authenticatee
I0125 15:16:57.247735 25325 authenticatee.cpp:121] Creating new client SASL connection
I0125 15:16:57.247905 25325 master.cpp:7001] Authenticating slave(94)@172.17.0.3:57726
I0125 15:16:57.247949 25325 status_update_manager.cpp:323] Received status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.248000 25325 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(222)@172.17.0.3:57726
I0125 15:16:57.248051 25325 slave.cpp:4090] Status update manager successfully handled status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.248071 25325 slave.cpp:4106] Sending acknowledgement for status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to executor(36)@172.17.0.3:57726
I0125 15:16:57.248119 25325 authenticator.cpp:98] Creating new server SASL connection
I0125 15:16:57.248225 25325 exec.cpp:369] Executor received status update acknowledgement adf6618e-4d53-4a0a-8364-f822a1acf41f for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.248257 25325 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0125 15:16:57.248278 25325 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0125 15:16:57.248311 25325 authenticator.cpp:204] Received SASL authentication start
I0125 15:16:57.248352 25325 authenticator.cpp:326] Authentication requires more steps
I0125 15:16:57.248383 25325 authenticatee.cpp:259] Received SASL authentication step
I0125 15:16:57.248416 25325 authenticator.cpp:232] Received SASL authentication step
I0125 15:16:57.248431 25325 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0125 15:16:57.248440 25325 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0125 15:16:57.248450 25325 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0125 15:16:57.248457 25325 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0125 15:16:57.248462 25325 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.248466 25325 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0125 15:16:57.248476 25325 authenticator.cpp:318] Authentication success
I0125 15:16:57.248518 25325 authenticatee.cpp:299] Authentication success
I0125 15:16:57.248546 25325 master.cpp:7031] Successfully authenticated principal 'test-principal' at slave(94)@172.17.0.3:57726
I0125 15:16:57.248570 25325 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(222)@172.17.0.3:57726
I0125 15:16:57.248622 25325 slave.cpp:1086] Successfully authenticated with master master@172.17.0.3:57726
I0125 15:16:57.248702 25325 slave.cpp:1508] Will retry registration in 18.992503ms if necessary
I0125 15:16:57.248834 25325 master.cpp:5522] Re-registering agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.249008 25325 registrar.cpp:461] Applied 1 operations in 26320ns; attempting to update the registry
I0125 15:16:57.249282 25325 registrar.cpp:506] Successfully updated the registry in 0ns
I0125 15:16:57.249460 25325 master.cpp:8882] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.249578 25325 master.cpp:5694] Re-registered agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0125 15:16:57.249624 25325 master.cpp:5802] Sending updated checkpointed resources {} to agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.249718 25325 hierarchical.cpp:478] Added agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0125 15:16:57.249862 25325 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.249879 25325 hierarchical.cpp:1302] Performed allocation for agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 144682ns
I0125 15:16:57.249923 25325 slave.cpp:1240] Re-registered with master master@172.17.0.3:57726
I0125 15:16:57.249945 25325 slave.cpp:1277] Forwarding total oversubscribed resources {}
I0125 15:16:57.249994 25325 slave.cpp:2830] Ignoring new checkpointed resources identical to the current version: {}
I0125 15:16:57.250017 25325 slave.cpp:4286] Received ping from slave-observer(96)@172.17.0.3:57726
I0125 15:16:57.250128 25325 master.cpp:6830] Sending 1 offers to framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.250182 25325 master.cpp:5863] Received update of agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) with total oversubscribed resources {}
I0125 15:16:57.250241 25325 status_update_manager.cpp:184] Resuming sending status updates
W0125 15:16:57.250252 25325 status_update_manager.cpp:191] Resending status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.250267 25325 status_update_manager.cpp:377] Forwarding update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to the agent
I0125 15:16:57.250396 25325 sched.cpp:933] Scheduler::resourceOffers took 13924ns
I0125 15:16:57.250452 25325 hierarchical.cpp:548] Agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0125 15:16:57.250499 25325 hierarchical.cpp:1677] No allocations performed
I0125 15:16:57.250514 25325 hierarchical.cpp:1772] No inverse offers to send out!
I0125 15:16:57.250529 25325 hierarchical.cpp:1302] Performed allocation for agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 55022ns
I0125 15:16:57.250571 25325 slave.cpp:4196] Forwarding the update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to master@172.17.0.3:57726
I0125 15:16:57.250669 25325 master.cpp:6008] Status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.250689 25325 master.cpp:6076] Forwarding status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.250733 25325 master.cpp:8138] Updating the state of task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I0125 15:16:57.250803 25325 sched.cpp:1041] Scheduler::statusUpdate took 25761ns
I0125 15:16:57.250862 25325 master.cpp:5015] Processing ACKNOWLEDGE call adf6618e-4d53-4a0a-8364-f822a1acf41f for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
I0125 15:16:57.250885 25325 master.cpp:8232] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.250984 25325 status_update_manager.cpp:395] Received status update acknowledgement (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.251021 25325 status_update_manager.cpp:531] Cleaning up status update stream for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.251101 25325 slave.cpp:3045] Status update manager successfully handled status update acknowledgement (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.251116 25325 slave.cpp:6721] Completing task 1
I0125 15:16:57.251276 25327 master.cpp:6528] Performing explicit task state reconciliation for 1 tasks of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.251310 25327 master.cpp:6658] Sending explicit reconciliation state TASK_UNKNOWN for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.251400 25321 sched.cpp:1041] Scheduler::statusUpdate took 19457ns
I0125 15:16:57.252044 25324 process.cpp:3697] Handling HTTP event for process 'master' with path: '/master/state'
I0125 15:16:57.252405 25325 http.cpp:420] HTTP GET for /master/state from 172.17.0.3:47454
I0125 15:16:57.262833 25314 sched.cpp:2021] Asked to stop the driver
I0125 15:16:57.262905 25317 sched.cpp:1203] Stopping framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.263093 25327 master.cpp:7543] Processing TEARDOWN call for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.263118 25327 master.cpp:7555] Removing framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.263162 25327 master.cpp:3078] Deactivating framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726
I0125 15:16:57.263269 25325 hierarchical.cpp:386] Deactivated framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.263411 25327 master.cpp:8261] Removing executor 'default' with resources {} of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.263497 25315 slave.cpp:2598] Asked to shut down framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 by master@172.17.0.3:57726
I0125 15:16:57.263595 25315 slave.cpp:2623] Shutting down framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.263659 25315 slave.cpp:5005] Shutting down executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at executor(36)@172.17.0.3:57726
I0125 15:16:57.263728 25315 exec.cpp:410] Executor asked to shutdown
I0125 15:16:57.263756 25315 exec.cpp:425] Executor::shutdown took 17870ns
I0125 15:16:57.263811 25315 slave.cpp:4328] Got exited event for executor(36)@172.17.0.3:57726
I0125 15:16:57.263916 25325 hierarchical.cpp:1011] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 from framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.264025 25325 hierarchical.cpp:337] Removed framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.264405 25315 slave.cpp:4691] Executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 exited with status 0
I0125 15:16:57.264453 25315 slave.cpp:4791] Cleaning up executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at executor(36)@172.17.0.3:57726
W0125 15:16:57.264505 25321 master.cpp:6132] Ignoring unknown exited executor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.264669 25325 gc.cpp:55] Scheduling '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452' for gc 6.99999693789333days in the future
I0125 15:16:57.264698 25315 slave.cpp:4879] Cleaning up framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.264727 25325 gc.cpp:55] Scheduling '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default' for gc 6.99999693700148days in the future
I0125 15:16:57.264781 25325 status_update_manager.cpp:285] Closing status update streams for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000
I0125 15:16:57.264807 25315 gc.cpp:55] Scheduling '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000' for gc 6.99999693552days in the future
I0125 15:16:57.264999 25321 slave.cpp:801] Agent terminating
I0125 15:16:57.265214 25323 master.cpp:1261] Agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) disconnected
I0125 15:16:57.265230 25323 master.cpp:3115] Disconnecting agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.265259 25323 master.cpp:3134] Deactivating agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc)
I0125 15:16:57.265339 25319 hierarchical.cpp:577] Agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 deactivated
I0125 15:16:57.269418 25314 master.cpp:1100] Master terminating
I0125 15:16:57.269567 25322 hierarchical.cpp:510] Removed agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0
[       OK ] PartitionTest.PartitionAwareTaskCompletedOnPartitionedAgent (51 ms)
{noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)


Mime
View raw message