[
https://issues.apache.org/jira/browse/MESOS-6990?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16625569#comment-16625569
]
Benno Evers commented on MESOS-6990:
------------------------------------
We observed another variant of this flake:
{noformat}
23:52:00 ../../src/tests/partition_tests.cpp:2403: Failure
23:52:00 Expected: TASK_FINISHED
23:52:00 To be equal to: finishedStatus->state()
23:52:00 Which is: TASK_RUNNING
{noformat}
Full Log:
{noformat}
23:52:00 [ RUN ] PartitionTest.TaskCompletedOnPartitionedAgent
23:52:00 I0922 23:52:00.328589 24617 cluster.cpp:173] Creating default 'local'
authorizer
23:52:00 I0922 23:52:00.329305 24634 master.cpp:413] Master
b5b3d76c-bb1e-4ebb-9638-26622f7abd87 (localhost) started on 127.0.0.1:45583
23:52:00 I0922 23:52:00.329325 24634 master.cpp:416] Flags at startup:
--acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/FBFVHM/credentials" --filter_gpu_resources="true"
--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" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --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"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/FBFVHM/master" --zk_session_timeout="10secs"
23:52:00 W0922 23:52:00.329428 24634 master.cpp:419]
23:52:00 **************************************************
23:52:00 Master bound to loopback interface! Cannot communicate with remote
schedulers or agents. You might want to set '--ip' flag to a routable IP
address.
23:52:00 **************************************************
23:52:00 I0922 23:52:00.329445 24634 master.cpp:465] Master only allowing
authenticated frameworks to register
23:52:00 I0922 23:52:00.329450 24634 master.cpp:471] Master only allowing
authenticated agents to register
23:52:00 I0922 23:52:00.329457 24634 master.cpp:477] Master only allowing
authenticated HTTP frameworks to register
23:52:00 I0922 23:52:00.329463 24634 credentials.hpp:37] Loading credentials
for authentication from '/tmp/FBFVHM/credentials'
23:52:00 I0922 23:52:00.329524 24634 master.cpp:521] Using default 'crammd5'
authenticator
23:52:00 I0922 23:52:00.329558 24634 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readonly'
23:52:00 I0922 23:52:00.329591 24634 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readwrite'
23:52:00 I0922 23:52:00.329612 24634 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-scheduler'
23:52:00 I0922 23:52:00.329629 24634 master.cpp:602] Authorization enabled
23:52:00 I0922 23:52:00.330214 24634 hierarchical.cpp:182] Initialized
hierarchical allocator process
23:52:00 I0922 23:52:00.330240 24634 whitelist_watcher.cpp:77] No whitelist
given
23:52:00 I0922 23:52:00.330646 24634 master.cpp:2083] Elected as the leading
master!
23:52:00 I0922 23:52:00.330659 24634 master.cpp:1638] Recovering from registrar
23:52:00 I0922 23:52:00.330688 24634 registrar.cpp:339] Recovering registrar
23:52:00 I0922 23:52:00.330797 24634 registrar.cpp:383] Successfully fetched
the registry (0B) in 0ns
23:52:00 I0922 23:52:00.330824 24634 registrar.cpp:487] Applied 1 operations
in 7558ns; attempting to update the registry
23:52:00 I0922 23:52:00.330925 24634 registrar.cpp:544] Successfully updated
the registry in 0ns
23:52:00 I0922 23:52:00.330948 24634 registrar.cpp:416] Successfully recovered
registrar
23:52:00 I0922 23:52:00.331012 24634 master.cpp:1752] Recovered 0 agents from
the registry (125B); allowing 10mins for agents to reregister
23:52:00 I0922 23:52:00.331073 24634 hierarchical.cpp:220] Skipping recovery
of hierarchical allocator: nothing to recover
23:52:00 W0922 23:52:00.332701 24617 process.cpp:2810] Attempted to spawn
already running process [email protected]:45583
23:52:00 I0922 23:52:00.332895 24617 cluster.cpp:485] Creating default 'local'
authorizer
23:52:00 I0922 23:52:00.333431 24631 slave.cpp:267] Mesos agent started on
(396)@127.0.0.1:45583
23:52:00 W0922 23:52:00.333573 24617 sched.cpp:1714]
23:52:00 **************************************************
23:52:00 Scheduler driver bound to loopback interface! Cannot communicate with
remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to
use a routable IP address.
23:52:00 **************************************************
23:52:00 I0922 23:52:00.333451 24631 slave.cpp:268] Flags at startup:
--acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --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_TDFm7O/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--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/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/jwt_secret_key"
--launcher="linux"
--launcher_dir="/home/admin/workspace/mesos/Mesos_CI-build/FLAG/SSL_GRPC/label/mesos-ec2-debian-9/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --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_TDFm7O"
--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_CWWDUi"
--zk_session_timeout="10secs"
23:52:00 W0922 23:52:00.333604 24617 process.cpp:2810] Attempted to spawn
already running process [email protected]:45583
23:52:00 W0922 23:52:00.333616 24631 slave.cpp:271]
23:52:00 **************************************************
23:52:00 Agent bound to loopback interface! Cannot communicate with remote
master(s). You might want to set '--ip' flag to a routable IP address.
23:52:00 **************************************************
23:52:00 I0922 23:52:00.333626 24631 credentials.hpp:86] Loading credential
for authentication from
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/credential'
23:52:00 I0922 23:52:00.333664 24631 slave.cpp:300] Agent using credential
for: test-principal
23:52:00 I0922 23:52:00.333678 24631 credentials.hpp:37] Loading credentials
for authentication from
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_TDFm7O/http_credentials'
23:52:00 I0922 23:52:00.333732 24631 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-executor'
23:52:00 I0922 23:52:00.333768 24631 http.cpp:1058] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-executor'
23:52:00 I0922 23:52:00.333824 24631 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readonly'
23:52:00 I0922 23:52:00.333848 24631 http.cpp:1058] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-readonly'
23:52:00 I0922 23:52:00.333892 24631 http.cpp:1037] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readwrite'
23:52:00 I0922 23:52:00.333942 24631 http.cpp:1058] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-readwrite'
23:52:00 I0922 23:52:00.334020 24631 disk_profile_adaptor.cpp:80] Creating
default disk profile adaptor module
23:52:00 I0922 23:52:00.334183 24631 slave.cpp:615] Agent resources:
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
23:52:00 I0922 23:52:00.334225 24631 slave.cpp:623] Agent attributes: [ ]
23:52:00 I0922 23:52:00.334229 24631 slave.cpp:632] Agent hostname: localhost
23:52:00 I0922 23:52:00.334779 24632 state.cpp:66] Recovering state from
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/meta'
23:52:00 I0922 23:52:00.334849 24635 slave.cpp:6909] Finished recovering
checkpointed state from
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/meta', beginning
agent recovery
23:52:00 I0922 23:52:00.334910 24637 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:52:00 I0922 23:52:00.335026 24637 task_status_update_manager.cpp:207]
Recovering task status update manager
23:52:00 I0922 23:52:00.335052 24617 sched.cpp:232] Version: 1.8.0
23:52:00 I0922 23:52:00.335397 24636 composing.cpp:339] Finished recovering
all containerizers
23:52:00 I0922 23:52:00.335501 24632 slave.cpp:7138] Recovering executors
23:52:00 I0922 23:52:00.335532 24632 slave.cpp:7291] Finished recovery
23:52:00 I0922 23:52:00.335860 24631 sched.cpp:336] New master detected at
[email protected]:45583
23:52:00 I0922 23:52:00.335865 24633 slave.cpp:1254] New master detected at
[email protected]:45583
23:52:00 I0922 23:52:00.335901 24634 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:52:00 I0922 23:52:00.335923 24633 slave.cpp:1319] Detecting new master
23:52:00 I0922 23:52:00.335963 24631 sched.cpp:401] Authenticating with master
[email protected]:45583
23:52:00 I0922 23:52:00.335976 24631 sched.cpp:408] Using default CRAM-MD5
authenticatee
23:52:00 I0922 23:52:00.336056 24636 authenticatee.cpp:121] Creating new
client SASL connection
23:52:00 I0922 23:52:00.336086 24631 slave.cpp:1346] Authenticating with
master [email protected]:45583
23:52:00 I0922 23:52:00.336103 24631 slave.cpp:1355] Using default CRAM-MD5
authenticatee
23:52:00 I0922 23:52:00.336148 24636 master.cpp:9653] Authenticating
[email protected]:45583
23:52:00 I0922 23:52:00.336154 24631 authenticatee.cpp:121] Creating new
client SASL connection
23:52:00 I0922 23:52:00.336184 24636 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(826)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336246 24636 authenticator.cpp:98] Creating new server
SASL connection
23:52:00 I0922 23:52:00.336252 24631 master.cpp:9653] Authenticating
slave(396)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336284 24631 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(827)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336319 24636 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
23:52:00 I0922 23:52:00.336326 24631 authenticator.cpp:98] Creating new server
SASL connection
23:52:00 I0922 23:52:00.336333 24636 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
23:52:00 I0922 23:52:00.336359 24636 authenticator.cpp:204] Received SASL
authentication start
23:52:00 I0922 23:52:00.336386 24631 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
23:52:00 I0922 23:52:00.336390 24636 authenticator.cpp:326] Authentication
requires more steps
23:52:00 I0922 23:52:00.336396 24631 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
23:52:00 I0922 23:52:00.336421 24636 authenticatee.cpp:259] Received SASL
authentication step
23:52:00 I0922 23:52:00.336459 24636 authenticator.cpp:232] Received SASL
authentication step
23:52:00 I0922 23:52:00.336474 24631 authenticator.cpp:204] Received SASL
authentication start
23:52:00 I0922 23:52:00.336477 24636 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
23:52:00 I0922 23:52:00.336490 24636 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
23:52:00 I0922 23:52:00.336500 24636 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
23:52:00 I0922 23:52:00.336504 24631 authenticator.cpp:326] Authentication
requires more steps
23:52:00 I0922 23:52:00.336509 24636 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
23:52:00 I0922 23:52:00.336514 24636 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.336520 24636 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.336532 24631 authenticatee.cpp:259] Received SASL
authentication step
23:52:00 I0922 23:52:00.336532 24636 authenticator.cpp:318] Authentication
success
23:52:00 I0922 23:52:00.336563 24631 authenticatee.cpp:299] Authentication
success
23:52:00 I0922 23:52:00.336575 24636 authenticator.cpp:232] Received SASL
authentication step
23:52:00 I0922 23:52:00.336585 24636 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
23:52:00 I0922 23:52:00.336592 24636 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
23:52:00 I0922 23:52:00.336606 24636 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
23:52:00 I0922 23:52:00.336599 24631 master.cpp:9685] Successfully
authenticated principal 'test-principal' at
[email protected]:45583
23:52:00 I0922 23:52:00.336616 24636 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
23:52:00 I0922 23:52:00.336623 24636 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.336627 24631 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(826)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336629 24636 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.336661 24636 authenticator.cpp:318] Authentication
success
23:52:00 I0922 23:52:00.336694 24636 authenticatee.cpp:299] Authentication
success
23:52:00 I0922 23:52:00.336743 24636 slave.cpp:1446] Successfully
authenticated with master [email protected]:45583
23:52:00 I0922 23:52:00.336755 24631 master.cpp:9685] Successfully
authenticated principal 'test-principal' at slave(396)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336809 24634 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(827)@127.0.0.1:45583
23:52:00 I0922 23:52:00.336856 24636 slave.cpp:1877] Will retry registration
in 4.494797ms if necessary
23:52:00 I0922 23:52:00.336899 24634 master.cpp:6605] Received register agent
message from slave(396)@127.0.0.1:45583 (localhost)
23:52:00 I0922 23:52:00.336907 24632 sched.cpp:513] Successfully authenticated
with master [email protected]:45583
23:52:00 I0922 23:52:00.336915 24632 sched.cpp:817] Sending SUBSCRIBE call to
[email protected]:45583
23:52:00 I0922 23:52:00.336946 24632 sched.cpp:850] Will retry registration in
768.375023ms if necessary
23:52:00 I0922 23:52:00.336959 24634 master.cpp:3964] Authorizing agent
providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with
principal 'test-principal'
23:52:00 I0922 23:52:00.337180 24634 master.cpp:2854] Received SUBSCRIBE call
for framework 'default' at
[email protected]:45583
23:52:00 I0922 23:52:00.337204 24634 master.cpp:2155] Authorizing framework
principal 'test-principal' to receive offers for roles '{ * }'
23:52:00 I0922 23:52:00.337255 24634 master.cpp:6672] Authorized registration
of agent at slave(396)@127.0.0.1:45583 (localhost)
23:52:00 I0922 23:52:00.337282 24634 master.cpp:6787] Registering agent at
slave(396)@127.0.0.1:45583 (localhost) with id
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.337386 24634 master.cpp:2935] Subscribing framework
default with checkpointing disabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
23:52:00 I0922 23:52:00.337396 24632 registrar.cpp:487] Applied 1 operations
in 37759ns; attempting to update the registry
23:52:00 I0922 23:52:00.337512 24632 registrar.cpp:544] Successfully updated
the registry in 0ns
23:52:00 I0922 23:52:00.337761 24634 master.cpp:9883] Adding framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 with roles { }
suppressed
23:52:00 I0922 23:52:00.337846 24634 master.cpp:6835] Admitted agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.337875 24632 hierarchical.cpp:306] Added framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.337947 24636 sched.cpp:744] Framework registered with
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.337956 24634 master.cpp:6880] Registered agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
23:52:00 I0922 23:52:00.337980 24632 hierarchical.cpp:1564] Performed
allocation for 0 agents in 78064ns
23:52:00 I0922 23:52:00.338016 24634 slave.cpp:1479] Registered with master
[email protected]:45583; given agent ID b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.338040 24632 hierarchical.cpp:601] Added agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 (localhost) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
23:52:00 I0922 23:52:00.338176 24634 slave.cpp:1499] Checkpointing SlaveInfo
to
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/meta/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/slave.info'
23:52:00 I0922 23:52:00.338194 24632 hierarchical.cpp:1564] Performed
allocation for 1 agents in 114095ns
23:52:00 I0922 23:52:00.338215 24632 task_status_update_manager.cpp:188]
Resuming sending task status updates
23:52:00 I0922 23:52:00.338304 24632 master.cpp:9468] Sending offers [
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-O0 ] to framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.337970 24636 sched.cpp:758] Scheduler::registered took
9368ns
23:52:00 I0922 23:52:00.338449 24636 sched.cpp:914] Scheduler::resourceOffers
took 26582ns
23:52:00 I0922 23:52:00.338451 24634 slave.cpp:1548] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"X6fWpYUrQNCyedUsPkWjiQ=="},"slave_id":{"value":"b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0"},"update_oversubscribed_resources":false}
23:52:00 I0922 23:52:00.338634 24634 master.cpp:7939] Ignoring update on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) as it reports no changes
23:52:00 I0922 23:52:00.349320 24635 master.cpp:11462] Removing offer
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-O0
23:52:00 I0922 23:52:00.349423 24635 master.cpp:4467] Processing ACCEPT call
for offers: [ b5b3d76c-bb1e-4ebb-9638-26622f7abd87-O0 ] on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) for framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default)
at [email protected]:45583
23:52:00 I0922 23:52:00.349469 24635 master.cpp:3541] Authorizing framework
principal 'test-principal' to launch task 1
23:52:00 W0922 23:52:00.349943 24638 validation.cpp:1444] 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.
23:52:00 W0922 23:52:00.350139 24638 validation.cpp:1456] 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.
23:52:00 I0922 23:52:00.350539 24638 master.cpp:12209] Adding task 1 with
resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024; ports(allocated: *):[31000-32000] on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.350790 24638 master.cpp:5439] Launching task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
on agent b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) on new executor
23:52:00 I0922 23:52:00.351167 24631 slave.cpp:2014] Got assigned task '1' for
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.351408 24631 slave.cpp:2388] Authorizing task '1' for
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.351433 24631 slave.cpp:8466] Authorizing framework
principal 'test-principal' to launch task 1
23:52:00 I0922 23:52:00.351845 24633 slave.cpp:2831] Launching task '1' for
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.351897 24633 paths.cpp:752] Creating sandbox
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
for user 'root'
23:52:00 I0922 23:52:00.352176 24633 slave.cpp:8994] Launching executor
'default' of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 with resources
[] in work directory
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
23:52:00 I0922 23:52:00.352396 24633 slave.cpp:3028] Queued task '1' for
executor 'default' of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.352435 24633 slave.cpp:988] Successfully attached
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
to virtual path
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/latest'
23:52:00 I0922 23:52:00.352529 24633 slave.cpp:3509] Launching container
61d68e5e-d6e4-46d1-a5c8-dd8787940fdf for executor 'default' of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.352650 24633 slave.cpp:988] Successfully attached
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
to virtual path
'/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/latest'
23:52:00 I0922 23:52:00.352674 24633 slave.cpp:988] Successfully attached
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
to virtual path
'/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_CWWDUi/slaves/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0/frameworks/b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000/executors/default/runs/61d68e5e-d6e4-46d1-a5c8-dd8787940fdf'
23:52:00 W0922 23:52:00.352937 24633 process.cpp:2810] Attempted to spawn
already running process [email protected]:45583
23:52:00 I0922 23:52:00.353013 24633 exec.cpp:162] Version: 1.8.0
23:52:00 I0922 23:52:00.353107 24633 exec.cpp:212] Executor started at:
executor(111)@127.0.0.1:45583 with pid 24617
23:52:00 I0922 23:52:00.353219 24635 slave.cpp:4803] Got registration for
executor 'default' of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.353384 24635 exec.cpp:236] Executor registered on
agent b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.353407 24635 exec.cpp:248] Executor::registered took
9171ns
23:52:00 I0922 23:52:00.353595 24632 slave.cpp:3241] Sending queued task '1'
to executor 'default' of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 at
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.353729 24636 exec.cpp:330] Executor asked to run task
'1'
23:52:00 I0922 23:52:00.353775 24636 exec.cpp:339] Executor::launchTask took
27079ns
23:52:00 I0922 23:52:00.353862 24631 exec.cpp:581] Executor sending status
update TASK_RUNNING (Status UUID: 0250639a-da72-46d2-8d09-d60251765f7c) for
task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.353940 24631 slave.cpp:5269] Handling status update
TASK_RUNNING (Status UUID: 0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.354096 24634 task_status_update_manager.cpp:328]
Received task status update TASK_RUNNING (Status UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354118 24634 task_status_update_manager.cpp:507]
Creating StatusUpdate stream for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354238 24634 task_status_update_manager.cpp:383]
Forwarding task status update TASK_RUNNING (Status UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to the agent
23:52:00 I0922 23:52:00.354312 24634 slave.cpp:5761] Forwarding the update
TASK_RUNNING (Status UUID: 0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to [email protected]:45583
23:52:00 I0922 23:52:00.354403 24636 master.cpp:8375] Status update
TASK_RUNNING (Status UUID: 0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.354426 24636 master.cpp:8432] Forwarding status update
TASK_RUNNING (Status UUID: 0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354476 24636 master.cpp:10932] Updating the state of
task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
23:52:00 I0922 23:52:00.354549 24636 sched.cpp:1022] Scheduler::statusUpdate
took 10025ns
23:52:00 I0922 23:52:00.354626 24636 master.cpp:6241] Processing ACKNOWLEDGE
call for status 0250639a-da72-46d2-8d09-d60251765f7c for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.354686 24634 slave.cpp:5654] Task status update
manager successfully handled status update TASK_RUNNING (Status UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354704 24634 slave.cpp:5670] Sending acknowledgement
for status update TASK_RUNNING (Status UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.354780 24634 task_status_update_manager.cpp:401]
Received task status update acknowledgement (UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354780 24632 exec.cpp:398] Executor received status
update acknowledgement 0250639a-da72-46d2-8d09-d60251765f7c for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.354849 24634 slave.cpp:4505] Task status update
manager successfully handled status update acknowledgement (UUID:
0250639a-da72-46d2-8d09-d60251765f7c) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.355082 24635 hierarchical.cpp:1564] Performed
allocation for 1 agents in 24492ns
23:52:00 I0922 23:52:00.355305 24632 hierarchical.cpp:1564] Performed
allocation for 1 agents in 21230ns
23:52:00 I0922 23:52:00.355479 24633 hierarchical.cpp:1564] Performed
allocation for 1 agents in 19986ns
23:52:00 I0922 23:52:00.355707 24632 hierarchical.cpp:1564] Performed
allocation for 1 agents in 20366ns
23:52:00 I0922 23:52:00.355707 24635 slave.cpp:6824] Current disk usage
36.54%. Max allowed age: 3.742041938120035days
23:52:00 I0922 23:52:00.355912 24635 hierarchical.cpp:1564] Performed
allocation for 1 agents in 21338ns
23:52:00 I0922 23:52:00.356022 24634 master.cpp:8765] Marking agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 (localhost) unreachable: health check
timed out
23:52:00 I0922 23:52:00.356132 24636 registrar.cpp:487] Applied 1 operations
in 21794ns; attempting to update the registry
23:52:00 I0922 23:52:00.356248 24636 registrar.cpp:544] Successfully updated
the registry in 0ns
23:52:00 I0922 23:52:00.356308 24636 master.cpp:8808] Marked agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 (localhost) unreachable: health check
timed out
23:52:00 I0922 23:52:00.356350 24636 master.cpp:10932] Updating the state of
task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (latest state:
TASK_LOST, status update state: TASK_LOST)
23:52:00 I0922 23:52:00.356417 24632 hierarchical.cpp:637] Removed agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.356434 24636 master.cpp:11030] Removing task 1 with
resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024; ports(allocated: *):[31000-32000] of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.356492 24636 master.cpp:8427] Sending status update
TASK_LOST for task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
'health check timed out'
23:52:00 I0922 23:52:00.356541 24636 master.cpp:11061] Removing executor
'default' with resources [] of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.356588 24632 sched.cpp:1022] Scheduler::statusUpdate
took 13348ns
23:52:00 I0922 23:52:00.356604 24636 master.cpp:2000] Notifying framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 of lost agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 (localhost)
23:52:00 I0922 23:52:00.356673 24634 sched.cpp:1084] Lost agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.356695 24634 sched.cpp:1095] Scheduler::slaveLost took
10718ns
23:52:00 I0922 23:52:00.356750 24637 exec.cpp:581] Executor sending status
update TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for
task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.356887 24636 slave.cpp:5269] Handling status update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.356941 24636 slave.cpp:1247] Lost leading master
23:52:00 I0922 23:52:00.356950 24636 slave.cpp:1319] Detecting new master
23:52:00 I0922 23:52:00.357031 24636 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:52:00 I0922 23:52:00.357092 24637 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:52:00 I0922 23:52:00.357091 24634 slave.cpp:1254] New master detected at
[email protected]:45583
23:52:00 I0922 23:52:00.357128 24634 slave.cpp:1319] Detecting new master
23:52:00 I0922 23:52:00.357188 24634 slave.cpp:1346] Authenticating with
master [email protected]:45583
23:52:00 I0922 23:52:00.357203 24634 slave.cpp:1355] Using default CRAM-MD5
authenticatee
23:52:00 I0922 23:52:00.357255 24634 authenticatee.cpp:121] Creating new
client SASL connection
23:52:00 I0922 23:52:00.357352 24632 master.cpp:9653] Authenticating
slave(396)@127.0.0.1:45583
23:52:00 I0922 23:52:00.357391 24632 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(828)@127.0.0.1:45583
23:52:00 I0922 23:52:00.357442 24632 authenticator.cpp:98] Creating new server
SASL connection
23:52:00 I0922 23:52:00.357553 24632 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
23:52:00 I0922 23:52:00.357570 24632 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
23:52:00 I0922 23:52:00.357600 24632 authenticator.cpp:204] Received SASL
authentication start
23:52:00 I0922 23:52:00.357628 24632 authenticator.cpp:326] Authentication
requires more steps
23:52:00 I0922 23:52:00.357666 24632 authenticatee.cpp:259] Received SASL
authentication step
23:52:00 I0922 23:52:00.357712 24632 authenticator.cpp:232] Received SASL
authentication step
23:52:00 I0922 23:52:00.357728 24632 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
23:52:00 I0922 23:52:00.357736 24632 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
23:52:00 I0922 23:52:00.357745 24632 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
23:52:00 I0922 23:52:00.357754 24632 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-122' server FQDN:
'ip-172-16-10-122' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
23:52:00 I0922 23:52:00.357760 24632 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.357766 24632 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
23:52:00 I0922 23:52:00.357777 24632 authenticator.cpp:318] Authentication
success
23:52:00 I0922 23:52:00.357822 24635 authenticatee.cpp:299] Authentication
success
23:52:00 I0922 23:52:00.357823 24636 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(828)@127.0.0.1:45583
23:52:00 I0922 23:52:00.357885 24635 slave.cpp:1446] Successfully
authenticated with master [email protected]:45583
23:52:00 I0922 23:52:00.358027 24635 slave.cpp:1877] Will retry registration
in 4.303138ms if necessary
23:52:00 I0922 23:52:00.358125 24632 master.cpp:9685] Successfully
authenticated principal 'test-principal' at slave(396)@127.0.0.1:45583
23:52:00 I0922 23:52:00.358189 24636 task_status_update_manager.cpp:328]
Received task status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.358245 24636 slave.cpp:5654] Task status update
manager successfully handled status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.358263 24636 slave.cpp:5670] Sending acknowledgement
for status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.358271 24632 master.cpp:6959] Received reregister
agent message from agent b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at
slave(396)@127.0.0.1:45583 (localhost)
23:52:00 I0922 23:52:00.358310 24636 exec.cpp:398] Executor received status
update acknowledgement 306e94d7-3412-4487-a62d-8763005ac5a7 for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.358355 24632 master.cpp:3964] Authorizing agent
providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with
principal 'test-principal'
23:52:00 I0922 23:52:00.358497 24636 master.cpp:7051] Authorized
re-registration of agent b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at
slave(396)@127.0.0.1:45583 (localhost)
23:52:00 I0922 23:52:00.358525 24636 master.cpp:7204] Consulting registry
about agent b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at
slave(396)@127.0.0.1:45583(localhost)
23:52:00 I0922 23:52:00.358636 24635 registrar.cpp:487] Applied 1 operations
in 39291ns; attempting to update the registry
23:52:00 I0922 23:52:00.358754 24635 registrar.cpp:544] Successfully updated
the registry in 0ns
23:52:00 I0922 23:52:00.358844 24635 master.cpp:7260] Re-admitted agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.358896 24635 master.cpp:8427] Sending status update
TASK_RUNNING for task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
'Unreachable agent re-reregistered'
23:52:00 I0922 23:52:00.358983 24635 master.cpp:12209] Adding task 1 with
resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024; ports(allocated: *):[31000-32000] on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.359108 24635 master.cpp:7457] Re-registered agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
23:52:00 I0922 23:52:00.359174 24632 sched.cpp:1022] Scheduler::statusUpdate
took 15602ns
23:52:00 I0922 23:52:00.359228 24632 slave.cpp:1585] Re-registered with master
[email protected]:45583
23:52:00 I0922 23:52:00.359251 24635 hierarchical.cpp:601] Added agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 (localhost) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: cpus(allocated: *):2; mem(allocated:
*):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000])
23:52:00 I0922 23:52:00.359277 24632 slave.cpp:1630] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"X6fWpYUrQNCyedUsPkWjiQ=="},"slave_id":{"value":"b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0"},"update_oversubscribed_resources":false}
23:52:00 I0922 23:52:00.359318 24635 hierarchical.cpp:1564] Performed
allocation for 1 agents in 21588ns
23:52:00 I0922 23:52:00.359340 24635 task_status_update_manager.cpp:188]
Resuming sending task status updates
23:52:00 W0922 23:52:00.359354 24635 task_status_update_manager.cpp:195]
Resending task status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.359367 24635 task_status_update_manager.cpp:383]
Forwarding task status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to the agent
23:52:00 I0922 23:52:00.359474 24636 master.cpp:7939] Ignoring update on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) as it reports no changes
23:52:00 I0922 23:52:00.359340 24632 slave.cpp:4067] Updating info for
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 with pid updated to
[email protected]:45583
23:52:00 I0922 23:52:00.359570 24635 task_status_update_manager.cpp:188]
Resuming sending task status updates
23:52:00 W0922 23:52:00.359581 24635 task_status_update_manager.cpp:195]
Resending task status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.359583 24632 slave.cpp:5761] Forwarding the update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to [email protected]:45583
23:52:00 I0922 23:52:00.359593 24635 task_status_update_manager.cpp:383]
Forwarding task status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to the agent
23:52:00 I0922 23:52:00.359663 24635 master.cpp:8375] Status update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.359684 24635 master.cpp:8432] Forwarding status update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.359741 24635 master.cpp:10932] Updating the state of
task 1 of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
23:52:00 I0922 23:52:00.359792 24636 sched.cpp:1022] Scheduler::statusUpdate
took 8288ns
23:52:00 I0922 23:52:00.359858 24636 master.cpp:6241] Processing ACKNOWLEDGE
call for status 306e94d7-3412-4487-a62d-8763005ac5a7 for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.359887 24636 master.cpp:11030] Removing task 1 with
resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated:
*):1024; ports(allocated: *):[31000-32000] of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.359896 24635 hierarchical.cpp:1236] Recovered
cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024;
ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: {}) on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 from framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.359941 24632 slave.cpp:5761] Forwarding the update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 to [email protected]:45583
23:52:00 I0922 23:52:00.360029 24632 task_status_update_manager.cpp:401]
Received task status update acknowledgement (UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.360064 24632 task_status_update_manager.cpp:538]
Cleaning up status update stream for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.360141 24632 slave.cpp:4505] Task status update
manager successfully handled status update acknowledgement (UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.360157 24632 slave.cpp:9651] Completing task 1
23:52:00 I0922 23:52:00.360167 24634 master.cpp:8375] Status update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.360188 24634 master.cpp:8432] Forwarding status update
TASK_FINISHED (Status UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 W0922 23:52:00.360225 24634 master.cpp:8405] Could not lookup task
for status update TASK_FINISHED (Status UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 from agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.360286 24634 sched.cpp:1022] Scheduler::statusUpdate
took 7377ns
23:52:00 I0922 23:52:00.360337 24634 master.cpp:6241] Processing ACKNOWLEDGE
call for status 306e94d7-3412-4487-a62d-8763005ac5a7 for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 I0922 23:52:00.360402 24634 task_status_update_manager.cpp:401]
Received task status update acknowledgement (UUID:
306e94d7-3412-4487-a62d-8763005ac5a7) for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 E0922 23:52:00.360447 24634 slave.cpp:4498] Failed to handle status
update acknowledgement (UUID: 306e94d7-3412-4487-a62d-8763005ac5a7) for task 1
of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000: Cannot find the task
status update stream for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 ../../src/tests/partition_tests.cpp:2403: Failure
23:52:00 Expected: TASK_FINISHED
23:52:00 To be equal to: finishedStatus->state()
23:52:00 Which is: TASK_RUNNING
23:52:00 I0922 23:52:00.360618 24638 master.cpp:8968] Performing explicit task
state reconciliation for 1 tasks of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.360648 24638 master.cpp:9129] Sending explicit
reconciliation state TASK_LOST for task 1 of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.360723 24638 sched.cpp:1022] Scheduler::statusUpdate
took 11664ns
23:52:00 I0922 23:52:00.361272 24633 process.cpp:3569] Handling HTTP event for
process 'master' with path: '/master/state'
23:52:00 I0922 23:52:00.361572 24632 http.cpp:1177] HTTP GET for /master/state
from 127.0.0.1:32870
23:52:00 I0922 23:52:00.362886 24617 sched.cpp:2008] Asked to stop the driver
23:52:00 I0922 23:52:00.362958 24638 sched.cpp:1184] Stopping framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.363030 24635 master.cpp:10185] Processing TEARDOWN
call for framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.363046 24635 master.cpp:10197] Removing framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.363055 24635 master.cpp:3230] Deactivating framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 (default) at
[email protected]:45583
23:52:00 I0922 23:52:00.363095 24635 master.cpp:11061] Removing executor
'default' with resources [] of framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 on agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.363158 24631 hierarchical.cpp:420] Deactivated
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.363189 24631 slave.cpp:3896] Asked to shut down
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 by [email protected]:45583
23:52:00 I0922 23:52:00.363199 24631 slave.cpp:3921] Shutting down framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.363207 24631 slave.cpp:6640] Shutting down executor
'default' of framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 at
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.363250 24631 exec.cpp:445] Executor asked to shutdown
23:52:00
23:52:00 GMOCK WARNING:
23:52:00 Uninteresting mock function call - returning directly.
23:52:00 Function call: shutdown(0x7f3d80041d90)
23:52:00 NOTE: You can safely ignore the above warning unless this call should
not happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't
mean to enforce the call. See
https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect
for details.
23:52:00 I0922 23:52:00.363276 24631 exec.cpp:460] Executor::shutdown took
17405ns
23:52:00 I0922 23:52:00.363407 24637 slave.cpp:5893] Got exited event for
executor(111)@127.0.0.1:45583
23:52:00 I0922 23:52:00.363487 24631 hierarchical.cpp:359] Removed framework
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000
23:52:00 I0922 23:52:00.363847 24617 slave.cpp:909] Agent terminating
23:52:00 I0922 23:52:00.363988 24617 slave.cpp:3896] Asked to shut down
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 by @0.0.0.0:0
23:52:00 W0922 23:52:00.364009 24617 slave.cpp:3917] Ignoring shutdown
framework b5b3d76c-bb1e-4ebb-9638-26622f7abd87-0000 because it is terminating
23:52:00 I0922 23:52:00.365259 24632 master.cpp:1251] Agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost) disconnected
23:52:00 I0922 23:52:00.365283 24632 master.cpp:3267] Disconnecting agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.365298 24632 master.cpp:3286] Deactivating agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 at slave(396)@127.0.0.1:45583
(localhost)
23:52:00 I0922 23:52:00.365336 24632 hierarchical.cpp:795] Agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0 deactivated
23:52:00 I0922 23:52:00.373523 24617 master.cpp:1093] Master terminating
23:52:00 I0922 23:52:00.373613 24635 hierarchical.cpp:637] Removed agent
b5b3d76c-bb1e-4ebb-9638-26622f7abd87-S0
23:52:00 [ FAILED ] PartitionTest.TaskCompletedOnPartitionedAgent (48 ms)
{noformat}
> PartitionTest.TaskCompletedOnPartitionedAgent is flaky.
> -------------------------------------------------------
>
> Key: MESOS-6990
> URL: https://issues.apache.org/jira/browse/MESOS-6990
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Michael Park
> Priority: Major
>
> 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
> [email protected]: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
> [email protected]:57726
> I0125 15:16:42.178993 25323 sched.cpp:407] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]:57726
> I0125 15:16:42.179983 25323 sched.cpp:836] Sending SUBSCRIBE call to
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]:57726 disconnected
> I0125 15:16:57.211426 25326 master.cpp:3078] Deactivating framework
> 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at
> [email protected]: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
> [email protected]:57726
> I0125 15:16:57.211701 25326 master.cpp:1393] Giving framework
> 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at
> [email protected]: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
> [email protected]:57726
> I0125 15:16:57.212059 25326 master.cpp:7555] Removing framework
> 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at
> [email protected]: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 [email protected]: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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
