[prev in list] [next in list] [prev in thread] [next in thread] 

List:       mesos-issues
Subject:    [jira] [Commented] (MESOS-6519) MasterTest.OrphanTasksMultipleAgents
From:       "Vinod Kone (JIRA)" <jira () apache ! org>
Date:       2016-10-31 21:16:58
Message-ID: JIRA.13016732.1477948253000.137464.1477948618376 () Atlassian ! JIRA
[Download RAW message or body]


    [ https://issues.apache.org/jira/browse/MESOS-6519?page=com.atlassian.jira.plugin. \
system.issuetabpanels:comment-tabpanel&focusedCommentId=15623445#comment-15623445 ] 

Vinod Kone commented on MESOS-6519:
-----------------------------------

This is due to the fact that we don't properly wait for both the agents to finish \
re-registration before querying the state endpoint.  If one of the agents re-tries \
the re-registration (e.g., auth timeout) master sends 2 `SlaveReregisteredMessage` \
messages the following test code finishes which is incorrect.

{code}
  Future<SlaveReregisteredMessage> slaveReregisteredMessage1 =
    FUTURE_PROTOBUF(SlaveReregisteredMessage(), _, _);

  Future<SlaveReregisteredMessage> slaveReregisteredMessage2 =
    FUTURE_PROTOBUF(SlaveReregisteredMessage(), _, _);

  // Failover the master.
  master->reset();
  master = StartMaster();
  ASSERT_SOME(master);

  // Simulate a new master detected event to the slaves (but not the scheduler).
  slavesDetector.appoint(master.get()->pid);

  AWAIT_READY(slaveReregisteredMessage1);
  AWAIT_READY(slaveReregisteredMessage2);
{code}

Fix is to include the correct PID in the `FUTURE_PROTOBUF` calls.

> MasterTest.OrphanTasksMultipleAgents
> ------------------------------------
> 
> Key: MESOS-6519
> URL: https://issues.apache.org/jira/browse/MESOS-6519
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Reporter: Vinod Kone
> Assignee: Vinod Kone
> Labels: flaky-test
> 
> Observed this on ASF CI.
> {code}
> [ RUN      ] MasterTest.OrphanTasksMultipleAgents
> I1031 14:54:18.459671 31623 cluster.cpp:158] Creating default 'local' authorizer
> I1031 14:54:18.462911 31623 leveldb.cpp:174] Opened db in 2.965951ms
> I1031 14:54:18.464269 31623 leveldb.cpp:181] Compacted db in 1.31548ms
> I1031 14:54:18.464326 31623 leveldb.cpp:196] Created db iterator in 13188ns
> I1031 14:54:18.464341 31623 leveldb.cpp:202] Seeked to beginning of db in 1625ns
> I1031 14:54:18.464349 31623 leveldb.cpp:271] Iterated through 0 keys in the db in \
> 150ns I1031 14:54:18.464380 31623 replica.cpp:776] Replica recovered with log \
> positions 0 -> 0 with 1 holes and 0 unlearned I1031 14:54:18.465016 31646 \
> recover.cpp:451] Starting replica recovery I1031 14:54:18.465349 31646 \
> recover.cpp:477] Replica is in EMPTY status I1031 14:54:18.466303 31647 \
> replica.cpp:673] Replica in EMPTY status received a broadcasted recover request \
> from __req_res__(2991)@172.17.0.3:46956 I1031 14:54:18.466681 31653 \
> recover.cpp:197] Received a recover response from a replica in EMPTY status I1031 \
> 14:54:18.467151 31649 recover.cpp:568] Updating replica status to STARTING I1031 \
> 14:54:18.467964 31655 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb \
> took 578744ns I1031 14:54:18.467994 31655 replica.cpp:320] Persisted replica status \
> to STARTING I1031 14:54:18.468024 31651 master.cpp:380] Master \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27 (173b586c223f) started on 172.17.0.3:46956 \
> I1031 14:54:18.468204 31655 recover.cpp:477] Replica is in STARTING status I1031 \
> 14:54:18.468040 31651 master.cpp:382] Flags at startup: --acls="" \
> --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" \
> --allocation_interval="1secs" --allocator="HierarchicalDRF" \
> --authenticate_agents="true" --authenticate_frameworks="true" \
> --authenticate_http_frameworks="true" --authenticate_http_readonly="true" \
> --authenticate_http_readwrite="true" --authenticators="crammd5" \
> --authorizers="local" --credentials="/tmp/ClEWj4/credentials" \
> --framework_sorter="drf" --help="false" --hostname_lookup="true" \
> --http_authenticators="basic" --http_framework_authenticators="basic" \
> --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" \
> --logging_level="INFO" --max_agent_ping_timeouts="5" \
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" \
> --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" \
> --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="/mesos/mesos-1.2.0/_inst/share/mesos/webui" \
> --work_dir="/tmp/ClEWj4/master" --zk_session_timeout="10secs" I1031 14:54:18.468483 \
> 31651 master.cpp:432] Master only allowing authenticated frameworks to register \
> I1031 14:54:18.468504 31651 master.cpp:446] Master only allowing authenticated \
> agents to register I1031 14:54:18.468520 31651 master.cpp:459] Master only allowing \
> authenticated HTTP frameworks to register I1031 14:54:18.468533 31651 \
> credentials.hpp:37] Loading credentials for authentication from \
> '/tmp/ClEWj4/credentials' I1031 14:54:18.468837 31651 master.cpp:504] Using default \
> 'crammd5' authenticator I1031 14:54:18.469027 31651 http.cpp:887] Using default \
> 'basic' HTTP authenticator for realm 'mesos-master-readonly' I1031 14:54:18.469029 \
> 31646 replica.cpp:673] Replica in STARTING status received a broadcasted recover \
> request from __req_res__(2992)@172.17.0.3:46956 I1031 14:54:18.469156 31651 \
> http.cpp:887] Using default 'basic' HTTP authenticator for realm \
> 'mesos-master-readwrite' I1031 14:54:18.469245 31651 http.cpp:887] Using default \
> 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I1031 14:54:18.469458 \
> 31651 master.cpp:584] Authorization enabled I1031 14:54:18.469560 31643 \
> recover.cpp:197] Received a recover response from a replica in STARTING status \
> I1031 14:54:18.469862 31653 hierarchical.cpp:149] Initialized hierarchical \
> allocator process I1031 14:54:18.469888 31646 whitelist_watcher.cpp:77] No \
> whitelist given I1031 14:54:18.470257 31647 recover.cpp:568] Updating replica \
> status to VOTING I1031 14:54:18.470875 31649 leveldb.cpp:304] Persisting metadata \
> (8 bytes) to leveldb took 400113ns I1031 14:54:18.470906 31649 replica.cpp:320] \
> Persisted replica status to VOTING I1031 14:54:18.471055 31650 recover.cpp:582] \
> Successfully joined the Paxos group I1031 14:54:18.471352 31650 recover.cpp:466] \
> Recover process terminated I1031 14:54:18.472995 31645 master.cpp:2033] Elected as \
> the leading master! I1031 14:54:18.473028 31645 master.cpp:1560] Recovering from \
> registrar I1031 14:54:18.473158 31653 registrar.cpp:329] Recovering registrar
> I1031 14:54:18.473791 31650 log.cpp:553] Attempting to start the writer
> I1031 14:54:18.475165 31650 replica.cpp:493] Replica received implicit promise \
> request from __req_res__(2993)@172.17.0.3:46956 with proposal 1 I1031 \
> 14:54:18.475623 31650 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb \
> took 419160ns I1031 14:54:18.475654 31650 replica.cpp:342] Persisted promised to 1
> I1031 14:54:18.476574 31649 coordinator.cpp:238] Coordinator attempting to fill \
> missing positions I1031 14:54:18.477970 31651 replica.cpp:388] Replica received \
> explicit promise request from __req_res__(2994)@172.17.0.3:46956 for position 0 \
> with proposal 2 I1031 14:54:18.478452 31651 leveldb.cpp:341] Persisting action (8 \
> bytes) to leveldb took 426215ns I1031 14:54:18.478488 31651 replica.cpp:708] \
> Persisted action NOP at position 0 I1031 14:54:18.479763 31653 replica.cpp:537] \
> Replica received write request for position 0 from \
> __req_res__(2995)@172.17.0.3:46956 I1031 14:54:18.479832 31653 leveldb.cpp:436] \
> Reading position from leveldb took 32539ns I1031 14:54:18.480396 31653 \
> leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 507365ns I1031 \
> 14:54:18.480428 31653 replica.cpp:708] Persisted action NOP at position 0 I1031 \
> 14:54:18.481135 31651 replica.cpp:691] Replica received learned notice for position \
> 0 from @0.0.0.0:0 I1031 14:54:18.481657 31651 leveldb.cpp:341] Persisting action \
> (16 bytes) to leveldb took 479094ns I1031 14:54:18.481688 31651 replica.cpp:708] \
> Persisted action NOP at position 0 I1031 14:54:18.482416 31647 log.cpp:569] Writer \
> started with ending position 0 I1031 14:54:18.483616 31646 leveldb.cpp:436] Reading \
> position from leveldb took 37294ns I1031 14:54:18.484666 31644 registrar.cpp:362] \
> Successfully fetched the registry (0B) in 11.421952ms I1031 14:54:18.484797 31644 \
> registrar.cpp:461] Applied 1 operations in 21474ns; attempting to update the \
> registry I1031 14:54:18.485672 31654 log.cpp:577] Attempting to append 168 bytes to \
> the log I1031 14:54:18.485873 31642 coordinator.cpp:348] Coordinator attempting to \
> write APPEND action at position 1 I1031 14:54:18.486687 31656 replica.cpp:537] \
> Replica received write request for position 1 from \
> __req_res__(2996)@172.17.0.3:46956 I1031 14:54:18.487164 31656 leveldb.cpp:341] \
> Persisting action (187 bytes) to leveldb took 429898ns I1031 14:54:18.487197 31656 \
> replica.cpp:708] Persisted action APPEND at position 1 I1031 14:54:18.488112 31651 \
> replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0 \
> I1031 14:54:18.488590 31651 leveldb.cpp:341] Persisting action (189 bytes) to \
> leveldb took 411110ns I1031 14:54:18.488622 31651 replica.cpp:708] Persisted action \
> APPEND at position 1 I1031 14:54:18.489761 31646 registrar.cpp:506] Successfully \
> updated the registry in 4.892928ms I1031 14:54:18.489938 31646 registrar.cpp:392] \
> Successfully recovered registrar I1031 14:54:18.490077 31649 log.cpp:596] \
> Attempting to truncate the log to 1 I1031 14:54:18.490211 31648 \
> coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2 \
> I1031 14:54:18.490653 31645 master.cpp:1676] Recovered 0 agents from the registry \
> (129B); allowing 10mins for agents to re-register I1031 14:54:18.490811 31657 \
> hierarchical.cpp:176] Skipping recovery of hierarchical allocator: nothing to \
> recover I1031 14:54:18.491212 31657 replica.cpp:537] Replica received write request \
> for position 2 from __req_res__(2997)@172.17.0.3:46956 I1031 14:54:18.491719 31657 \
> leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 461103ns I1031 \
> 14:54:18.491744 31657 replica.cpp:708] Persisted action TRUNCATE at position 2 \
> I1031 14:54:18.492624 31652 replica.cpp:691] Replica received learned notice for \
> position 2 from @0.0.0.0:0 I1031 14:54:18.492983 31652 leveldb.cpp:341] Persisting \
> action (18 bytes) to leveldb took 327074ns I1031 14:54:18.493051 31652 \
> leveldb.cpp:399] Deleting ~1 keys from leveldb took 39143ns I1031 14:54:18.493075 \
> 31652 replica.cpp:708] Persisted action TRUNCATE at position 2 I1031 \
> 14:54:18.497611 31623 cluster.cpp:435] Creating default 'local' authorizer I1031 \
> 14:54:18.499606 31654 slave.cpp:208] Mesos agent started on (198)@172.17.0.3:46956 \
> I1031 14:54:18.499665 31654 slave.cpp:209] 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/MasterTest_OrphanTasksMultipleAgents_qckwyX/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/MasterTest_OrphanTasksMultipleAgents_qckwyX/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/MasterTest_OrphanTasksMultipleAgents_qckwyX/http_credentials" \
> --image_provisioner_backend="copy" --initialize_driver_logging="true" \
> --isolation="posix/cpu,posix/mem" --launcher="posix" \
> --launcher_dir="/mesos/mesos-1.2.0/_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/MasterTest_OrphanTasksMultipleAgents_qckwyX" \
> --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/MasterTest_OrphanTasksMultipleAgents_FlWdW0" \
> I1031 14:54:18.500120 31654 credentials.hpp:86] Loading credential for \
> authentication from '/tmp/MasterTest_OrphanTasksMultipleAgents_qckwyX/credential' \
> I1031 14:54:18.500249 31654 slave.cpp:346] Agent using credential for: \
> test-principal I1031 14:54:18.500272 31654 credentials.hpp:37] Loading credentials \
> for authentication from \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_qckwyX/http_credentials' I1031 \
> 14:54:18.500517 31654 http.cpp:887] Using default 'basic' HTTP authenticator for \
> realm 'mesos-agent-readonly' I1031 14:54:18.500643 31654 http.cpp:887] Using \
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' I1031 \
> 14:54:18.500860 31623 sched.cpp:226] Version: 1.2.0 I1031 14:54:18.501534 31650 \
> sched.cpp:330] New master detected at master@172.17.0.3:46956 I1031 14:54:18.501624 \
> 31650 sched.cpp:396] Authenticating with master master@172.17.0.3:46956 I1031 \
> 14:54:18.501644 31650 sched.cpp:403] Using default CRAM-MD5 authenticatee I1031 \
> 14:54:18.501754 31654 slave.cpp:533] Agent resources: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] I1031 14:54:18.501847 31654 slave.cpp:541] \
> Agent attributes: [  ] I1031 14:54:18.501862 31654 slave.cpp:546] Agent hostname: \
> 173b586c223f I1031 14:54:18.501898 31656 authenticatee.cpp:121] Creating new client \
> SASL connection I1031 14:54:18.502148 31655 master.cpp:6742] Authenticating \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.502251 31644 authenticator.cpp:414] Starting authentication session for \
> crammd5-authenticatee(450)@172.17.0.3:46956 I1031 14:54:18.502460 31648 \
> authenticator.cpp:98] Creating new server SASL connection I1031 14:54:18.502676 \
> 31651 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 \
> I1031 14:54:18.502709 31651 authenticatee.cpp:239] Attempting to authenticate with \
> mechanism 'CRAM-MD5' I1031 14:54:18.502818 31650 authenticator.cpp:204] Received \
> SASL authentication start I1031 14:54:18.502918 31650 authenticator.cpp:326] \
> Authentication requires more steps I1031 14:54:18.503060 31656 \
> authenticatee.cpp:259] Received SASL authentication step I1031 14:54:18.503196 \
> 31656 authenticator.cpp:232] Received SASL authentication step I1031 \
> 14:54:18.503232 31656 auxprop.cpp:109] Request to lookup properties for user: \
> 'test-principal' realm: '173b586c223f' server FQDN: '173b586c223f' \
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: false  I1031 14:54:18.503258 31656 auxprop.cpp:181] Looking \
> up auxiliary property '*userPassword' I1031 14:54:18.503303 31656 auxprop.cpp:181] \
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1031 14:54:18.503343 31656 \
> auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: \
> '173b586c223f' server FQDN: '173b586c223f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false \
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true  I1031 14:54:18.503368 \
> 31656 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since \
> SASL_AUXPROP_AUTHZID == true I1031 14:54:18.503384 31656 auxprop.cpp:131] Skipping \
> auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true \
> I1031 14:54:18.503410 31656 authenticator.cpp:318] Authentication success I1031 \
> 14:54:18.503456 31646 state.cpp:57] Recovering state from \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_FlWdW0/meta' I1031 14:54:18.503504 31650 \
> authenticatee.cpp:299] Authentication success I1031 14:54:18.503566 31648 \
> master.cpp:6772] Successfully authenticated principal 'test-principal' at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.503651 31656 authenticator.cpp:432] Authentication session cleanup for \
> crammd5-authenticatee(450)@172.17.0.3:46956 I1031 14:54:18.503790 31645 \
> status_update_manager.cpp:203] Recovering status update manager I1031 \
> 14:54:18.504070 31649 sched.cpp:502] Successfully authenticated with master \
> master@172.17.0.3:46956 I1031 14:54:18.504091 31649 sched.cpp:820] Sending \
> SUBSCRIBE call to master@172.17.0.3:46956 I1031 14:54:18.504111 31652 \
> slave.cpp:5399] Finished recovery I1031 14:54:18.504182 31649 sched.cpp:853] Will \
> retry registration in 1.851789769secs if necessary I1031 14:54:18.504303 31647 \
> master.cpp:2612] Received SUBSCRIBE call for framework 'default' at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.504362 31647 master.cpp:2069] Authorizing framework principal \
> 'test-principal' to receive offers for role '*' I1031 14:54:18.504582 31652 \
> slave.cpp:5573] Querying resource estimator for oversubscribable resources I1031 \
> 14:54:18.504797 31654 master.cpp:2688] Subscribing framework default with \
> checkpointing disabled and capabilities [  ] I1031 14:54:18.505110 31657 \
> status_update_manager.cpp:177] Pausing sending status updates I1031 14:54:18.505115 \
> 31652 slave.cpp:915] New master detected at master@172.17.0.3:46956 I1031 \
> 14:54:18.505151 31652 slave.cpp:974] Authenticating with master \
> master@172.17.0.3:46956 I1031 14:54:18.505264 31652 slave.cpp:985] Using default \
> CRAM-MD5 authenticatee I1031 14:54:18.505445 31647 sched.cpp:743] Framework \
> registered with 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.505472 \
> 31643 hierarchical.cpp:275] Added framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.505555 31656 \
> authenticatee.cpp:121] Creating new client SASL connection I1031 14:54:18.505571 \
> 31647 sched.cpp:757] Scheduler::registered took 54451ns I1031 14:54:18.505614 31643 \
> hierarchical.cpp:1694] No allocations performed I1031 14:54:18.505658 31643 \
> hierarchical.cpp:1789] No inverse offers to send out! I1031 14:54:18.505724 31643 \
> hierarchical.cpp:1286] Performed allocation for 0 agents in 169452ns I1031 \
> 14:54:18.505501 31652 slave.cpp:947] Detecting new master I1031 14:54:18.505832 \
> 31654 master.cpp:6742] Authenticating slave(198)@172.17.0.3:46956 I1031 \
> 14:54:18.505985 31646 authenticator.cpp:414] Starting authentication session for \
> crammd5-authenticatee(451)@172.17.0.3:46956 I1031 14:54:18.506060 31652 \
> slave.cpp:5587] Received oversubscribable resources {} from the resource estimator \
> I1031 14:54:18.506244 31649 authenticator.cpp:98] Creating new server SASL \
> connection I1031 14:54:18.506481 31645 authenticatee.cpp:213] Received SASL \
> authentication mechanisms: CRAM-MD5 I1031 14:54:18.506525 31645 \
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I1031 \
> 14:54:18.506630 31645 authenticator.cpp:204] Received SASL authentication start \
> I1031 14:54:18.506705 31645 authenticator.cpp:326] Authentication requires more \
> steps I1031 14:54:18.506834 31643 authenticatee.cpp:259] Received SASL \
> authentication step I1031 14:54:18.507019 31652 authenticator.cpp:232] Received \
> SASL authentication step I1031 14:54:18.507063 31652 auxprop.cpp:109] Request to \
> lookup properties for user: 'test-principal' realm: '173b586c223f' server FQDN: \
> '173b586c223f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: false  I1031 14:54:18.507091 31652 auxprop.cpp:181] Looking \
> up auxiliary property '*userPassword' I1031 14:54:18.507139 31652 auxprop.cpp:181] \
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1031 14:54:18.507179 31652 \
> auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: \
> '173b586c223f' server FQDN: '173b586c223f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false \
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true  I1031 14:54:18.507203 \
> 31652 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since \
> SASL_AUXPROP_AUTHZID == true I1031 14:54:18.507226 31652 auxprop.cpp:131] Skipping \
> auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true \
> I1031 14:54:18.507256 31652 authenticator.cpp:318] Authentication success I1031 \
> 14:54:18.507359 31643 authenticatee.cpp:299] Authentication success I1031 \
> 14:54:18.507447 31642 master.cpp:6772] Successfully authenticated principal \
> 'test-principal' at slave(198)@172.17.0.3:46956 I1031 14:54:18.507532 31647 \
> authenticator.cpp:432] Authentication session cleanup for \
> crammd5-authenticatee(451)@172.17.0.3:46956 I1031 14:54:18.507719 31651 \
> slave.cpp:1069] Successfully authenticated with master master@172.17.0.3:46956 \
> I1031 14:54:18.507947 31651 slave.cpp:1483] Will retry registration in 11.127033ms \
> if necessary I1031 14:54:18.508164 31642 master.cpp:5151] Registering agent at \
> slave(198)@172.17.0.3:46956 (173b586c223f) with id \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 I1031 14:54:18.508657 31657 \
> registrar.cpp:461] Applied 1 operations in 57631ns; attempting to update the \
> registry I1031 14:54:18.509627 31643 log.cpp:577] Attempting to append 337 bytes to \
> the log I1031 14:54:18.509760 31653 coordinator.cpp:348] Coordinator attempting to \
> write APPEND action at position 3 I1031 14:54:18.510596 31656 replica.cpp:537] \
> Replica received write request for position 3 from \
> __req_res__(2998)@172.17.0.3:46956 I1031 14:54:18.511073 31656 leveldb.cpp:341] \
> Persisting action (356 bytes) to leveldb took 426870ns I1031 14:54:18.511107 31656 \
> I1031 14:54:18.512259 31650 leveldb.cpp:341] Persisting action (358 bytes) to \
> leveldb took 411830ns I1031 14:54:18.512291 31650 replica.cpp:708] Persisted action \
> APPEND at position 3 I1031 14:54:18.513923 31649 registrar.cpp:506] Successfully \
> updated the registry in 5.201152ms I1031 14:54:18.514209 31648 log.cpp:596] \
> Attempting to truncate the log to 3 I1031 14:54:18.514351 31656 \
> coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4 \
> I1031 14:54:18.514930 31655 slave.cpp:4251] Received ping from \
> slave-observer(200)@172.17.0.3:46956 I1031 14:54:18.515231 31643 replica.cpp:537] \
> Replica received write request for position 4 from \
> __req_res__(2999)@172.17.0.3:46956 I1031 14:54:18.515349 31657 slave.cpp:1115] \
> Registered with master master@172.17.0.3:46956; given agent ID \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 I1031 14:54:18.515388 31657 fetcher.cpp:86] \
> Clearing fetcher cache I1031 14:54:18.515269 31650 master.cpp:5222] Registered \
> agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] \
> I1031 14:54:18.515606 31646 status_update_manager.cpp:184] Resuming sending status \
> updates I1031 14:54:18.515758 31653 hierarchical.cpp:485] Added agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 (173b586c223f) with cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] (allocated: {}) I1031 14:54:18.515805 31643 \
> leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 522344ns I1031 \
> 14:54:18.515846 31643 replica.cpp:708] Persisted action TRUNCATE at position 4 \
> I1031 14:54:18.515928 31657 slave.cpp:1138] Checkpointing SlaveInfo to \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_FlWdW0/meta/slaves/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0/slave.info'
>  I1031 14:54:18.516572 31645 replica.cpp:691] Replica received learned notice for \
> position 4 from @0.0.0.0:0 I1031 14:54:18.516623 31657 slave.cpp:1175] Forwarding \
> total oversubscribed resources {} I1031 14:54:18.516993 31651 master.cpp:5621] \
> Received update of agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at \
> slave(198)@172.17.0.3:46956 (173b586c223f) with total oversubscribed resources {} \
> I1031 14:54:18.517125 31645 leveldb.cpp:341] Persisting action (18 bytes) to \
> leveldb took 508592ns I1031 14:54:18.517215 31645 leveldb.cpp:399] Deleting ~2 keys \
> from leveldb took 56423ns I1031 14:54:18.517243 31645 replica.cpp:708] Persisted \
> action TRUNCATE at position 4 I1031 14:54:18.517669 31653 hierarchical.cpp:1789] No \
> inverse offers to send out! I1031 14:54:18.517771 31653 hierarchical.cpp:1309] \
> Performed allocation for agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 in \
> 1.943202ms I1031 14:54:18.517973 31653 hierarchical.cpp:555] Agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 (173b586c223f) updated with oversubscribed \
> resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], \
> allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I1031 \
> 14:54:18.518121 31653 hierarchical.cpp:1694] No allocations performed I1031 \
> 14:54:18.518163 31653 hierarchical.cpp:1789] No inverse offers to send out! I1031 \
> 14:54:18.518216 31653 hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 in 190028ns I1031 14:54:18.518220 31643 \
> master.cpp:6571] Sending 1 offers to framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.518725 31654 sched.cpp:917] Scheduler::resourceOffers took 123398ns I1031 \
> 14:54:18.520814 31651 master.cpp:3581] Processing ACCEPT call for offers: [ \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-O0 ] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) for framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.520928 31651 master.cpp:3173] Authorizing framework principal \
> 'test-principal' to launch task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a W1031 \
> 14:54:18.523193 31655 validation.cpp:920] Executor 'default' for task \
> '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' uses less CPUs (None) than the minimum \
> required (0.01). Please update your executor, as this will be mandatory in future \
> releases. W1031 14:54:18.523232 31655 validation.cpp:932] Executor 'default' for \
> task '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' uses less memory (None) than the \
> minimum required (32MB). Please update your executor, as this will be mandatory in \
> future releases. I1031 14:54:18.523774 31655 master.cpp:8334] Adding task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a with resources cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 (173b586c223f) I1031 14:54:18.524137 31655 \
> master.cpp:4230] Launching task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 with resources \
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.524610 31653 slave.cpp:1547] Got assigned task \
> '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' for framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.525429 31653 \
> slave.cpp:1709] Launching task '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' for framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.526227 31653 \
> paths.cpp:536] Trying to chown \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_FlWdW0/slaves/5098f7d2-2044-4dcd-b97f-9bd \
> 7c3dd1e27-S0/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/b47eb823-9ff3-4386-bbd1-dc5f09b2d5a2' \
> to user 'mesos' I1031 14:54:18.534395 31653 slave.cpp:6307] Launching executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 with resources {} \
> in work directory '/tmp/MasterTest_OrphanTasksMultipleAgents_FlWdW0/slaves/5098f7d2- \
> 2044-4dcd-b97f-9bd7c3dd1e27-S0/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/b47eb823-9ff3-4386-bbd1-dc5f09b2d5a2'
>  I1031 14:54:18.537529 31653 exec.cpp:162] Version: 1.2.0
> I1031 14:54:18.537901 31654 exec.cpp:212] Executor started at: \
> executor(78)@172.17.0.3:46956 with pid 31623 I1031 14:54:18.538316 31653 \
> slave.cpp:2031] Queued task '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' for executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 \
> 14:54:18.538415 31653 slave.cpp:868] Successfully attached file \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_FlWdW0/slaves/5098f7d2-2044-4dcd-b97f-9bd \
> 7c3dd1e27-S0/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/b47eb823-9ff3-4386-bbd1-dc5f09b2d5a2'
>  I1031 14:54:18.538676 31653 slave.cpp:3305] Got registration for executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from \
> executor(78)@172.17.0.3:46956 I1031 14:54:18.539242 31655 exec.cpp:237] Executor \
> registered on agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 I1031 14:54:18.539305 \
> 31655 exec.cpp:249] Executor::registered took 31294ns I1031 14:54:18.539798 31653 \
> slave.cpp:2247] Sending queued task '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' to \
> executor 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 at \
> executor(78)@172.17.0.3:46956 I1031 14:54:18.540233 31644 exec.cpp:324] Executor \
> asked to run task '3d00a1fe-59e4-42cf-a231-df3a06aecc3a' I1031 14:54:18.540338 \
> 31644 exec.cpp:333] Executor::launchTask took 70083ns I1031 14:54:18.540446 31644 \
> exec.cpp:550] Executor sending status update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.540742 31644 \
> slave.cpp:3740] Handling status update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from \
> executor(78)@172.17.0.3:46956 I1031 14:54:18.541482 31653 \
> status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.541540 31653 \
> status_update_manager.cpp:500] Creating StatusUpdate stream for task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.542067 31653 \
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to the agent I1031 \
> 14:54:18.542498 31645 slave.cpp:4169] Forwarding the update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to master@172.17.0.3:46956 \
> I1031 14:54:18.542769 31645 slave.cpp:4063] Status update manager successfully \
> handled status update TASK_RUNNING (UUID: 5a86be7a-e823-4eb1-90e1-823aabd57613) for \
> task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.542840 31645 \
> slave.cpp:4079] Sending acknowledgement for status update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to \
> executor(78)@172.17.0.3:46956 I1031 14:54:18.542984 31643 master.cpp:5757] Status \
> update TASK_RUNNING (UUID: 5a86be7a-e823-4eb1-90e1-823aabd57613) for task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.543071 31644 exec.cpp:373] Executor received status \
> update acknowledgement 5a86be7a-e823-4eb1-90e1-823aabd57613 for task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.543071 31643 \
> master.cpp:5819] Forwarding status update TASK_RUNNING (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.543319 31643 \
> master.cpp:7712] Updating the state of task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of \
> framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (latest state: TASK_RUNNING, \
> status update state: TASK_RUNNING) I1031 14:54:18.543658 31657 sched.cpp:1025] \
> Scheduler::statusUpdate took 138896ns I1031 14:54:18.544138 31652 master.cpp:4867] \
> Processing ACKNOWLEDGE call 5a86be7a-e823-4eb1-90e1-823aabd57613 for task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 I1031 14:54:18.544566 31646 \
> status_update_manager.cpp:395] Received status update acknowledgement (UUID: \
> 5a86be7a-e823-4eb1-90e1-823aabd57613) for task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.544916 31652 \
> slave.cpp:3022] Status update manager successfully handled status update \
> acknowledgement (UUID: 5a86be7a-e823-4eb1-90e1-823aabd57613) for task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.547865 31623 \
> cluster.cpp:435] Creating default 'local' authorizer I1031 14:54:18.549728 31645 \
> slave.cpp:208] Mesos agent started on (199)@172.17.0.3:46956 I1031 14:54:18.549870 \
> 31645 slave.cpp:209] 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/MasterTest_OrphanTasksMultipleAgents_EVkMmK/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/MasterTest_OrphanTasksMultipleAgents_EVkMmK/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/MasterTest_OrphanTasksMultipleAgents_EVkMmK/http_credentials" \
> --image_provisioner_backend="copy" --initialize_driver_logging="true" \
> --isolation="posix/cpu,posix/mem" --launcher="posix" \
> --launcher_dir="/mesos/mesos-1.2.0/_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/MasterTest_OrphanTasksMultipleAgents_EVkMmK" \
> --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/MasterTest_OrphanTasksMultipleAgents_7SCiCN" \
> I1031 14:54:18.550590 31645 credentials.hpp:86] Loading credential for \
> authentication from '/tmp/MasterTest_OrphanTasksMultipleAgents_EVkMmK/credential' \
> I1031 14:54:18.550806 31645 slave.cpp:346] Agent using credential for: \
> test-principal I1031 14:54:18.550833 31645 credentials.hpp:37] Loading credentials \
> for authentication from \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_EVkMmK/http_credentials' I1031 \
> 14:54:18.551142 31645 http.cpp:887] Using default 'basic' HTTP authenticator for \
> realm 'mesos-agent-readonly' I1031 14:54:18.551317 31645 http.cpp:887] Using \
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' I1031 \
> 14:54:18.552794 31645 slave.cpp:533] Agent resources: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] I1031 14:54:18.552898 31645 slave.cpp:541] \
> Agent attributes: [  ] I1031 14:54:18.552917 31645 slave.cpp:546] Agent hostname: \
> 173b586c223f I1031 14:54:18.554693 31650 state.cpp:57] Recovering state from \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_7SCiCN/meta' I1031 14:54:18.555044 31646 \
> status_update_manager.cpp:203] Recovering status update manager I1031 \
> 14:54:18.555426 31643 slave.cpp:5399] Finished recovery I1031 14:54:18.555929 31643 \
> slave.cpp:5573] Querying resource estimator for oversubscribable resources I1031 \
> 14:54:18.556341 31656 status_update_manager.cpp:177] Pausing sending status updates \
> I1031 14:54:18.556361 31642 slave.cpp:915] New master detected at \
> master@172.17.0.3:46956 I1031 14:54:18.556391 31642 slave.cpp:974] Authenticating \
> with master master@172.17.0.3:46956 I1031 14:54:18.556450 31642 slave.cpp:985] \
> Using default CRAM-MD5 authenticatee I1031 14:54:18.556589 31642 slave.cpp:947] \
> Detecting new master I1031 14:54:18.556648 31654 authenticatee.cpp:121] Creating \
> new client SASL connection I1031 14:54:18.556732 31642 slave.cpp:5587] Received \
> oversubscribable resources {} from the resource estimator I1031 14:54:18.556872 \
> 31656 master.cpp:6742] Authenticating slave(199)@172.17.0.3:46956 I1031 \
> 14:54:18.556994 31655 authenticator.cpp:414] Starting authentication session for \
> crammd5-authenticatee(452)@172.17.0.3:46956 I1031 14:54:18.557211 31649 \
> authenticator.cpp:98] Creating new server SASL connection I1031 14:54:18.557438 \
> 31645 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 \
> I1031 14:54:18.557507 31645 authenticatee.cpp:239] Attempting to authenticate with \
> mechanism 'CRAM-MD5' I1031 14:54:18.557646 31647 authenticator.cpp:204] Received \
> SASL authentication start I1031 14:54:18.557719 31647 authenticator.cpp:326] \
> Authentication requires more steps I1031 14:54:18.557847 31645 \
> authenticatee.cpp:259] Received SASL authentication step I1031 14:54:18.558033 \
> 31652 authenticator.cpp:232] Received SASL authentication step I1031 \
> 14:54:18.558080 31652 auxprop.cpp:109] Request to lookup properties for user: \
> 'test-principal' realm: '173b586c223f' server FQDN: '173b586c223f' \
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: false  I1031 14:54:18.558109 31652 auxprop.cpp:181] Looking \
> up auxiliary property '*userPassword' I1031 14:54:18.558156 31652 auxprop.cpp:181] \
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1031 14:54:18.558184 31652 \
> auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: \
> '173b586c223f' server FQDN: '173b586c223f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false \
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true  I1031 14:54:18.558202 \
> 31652 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since \
> SASL_AUXPROP_AUTHZID == true I1031 14:54:18.558212 31652 auxprop.cpp:131] Skipping \
> auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true \
> I1031 14:54:18.558226 31652 authenticator.cpp:318] Authentication success I1031 \
> 14:54:18.558296 31642 authenticatee.cpp:299] Authentication success I1031 \
> 14:54:18.558343 31656 master.cpp:6772] Successfully authenticated principal \
> 'test-principal' at slave(199)@172.17.0.3:46956 I1031 14:54:18.558392 31657 \
> authenticator.cpp:432] Authentication session cleanup for \
> crammd5-authenticatee(452)@172.17.0.3:46956 I1031 14:54:18.558599 31650 \
> slave.cpp:1069] Successfully authenticated with master master@172.17.0.3:46956 \
> I1031 14:54:18.558734 31650 slave.cpp:1483] Will retry registration in 10.674123ms \
> if necessary I1031 14:54:18.558900 31652 master.cpp:5151] Registering agent at \
> slave(199)@172.17.0.3:46956 (173b586c223f) with id \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 I1031 14:54:18.559381 31642 \
> registrar.cpp:461] Applied 1 operations in 73404ns; attempting to update the \
> registry I1031 14:54:18.560248 31645 log.cpp:577] Attempting to append 503 bytes to \
> the log I1031 14:54:18.560426 31644 coordinator.cpp:348] Coordinator attempting to \
> write APPEND action at position 5 I1031 14:54:18.561122 31650 replica.cpp:537] \
> Replica received write request for position 5 from \
> __req_res__(3000)@172.17.0.3:46956 I1031 14:54:18.561779 31650 leveldb.cpp:341] \
> Persisting action (522 bytes) to leveldb took 611463ns I1031 14:54:18.561803 31650 \
> replica.cpp:708] Persisted action APPEND at position 5 I1031 14:54:18.562427 31645 \
> replica.cpp:691] Replica received learned notice for position 5 from @0.0.0.0:0 \
> I1031 14:54:18.562875 31645 leveldb.cpp:341] Persisting action (524 bytes) to \
> leveldb took 415244ns I1031 14:54:18.562902 31645 replica.cpp:708] Persisted action \
> APPEND at position 5 I1031 14:54:18.564662 31645 registrar.cpp:506] Successfully \
> updated the registry in 5.217024ms I1031 14:54:18.564867 31644 log.cpp:596] \
> Attempting to truncate the log to 5 I1031 14:54:18.565037 31645 \
> coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6 \
> I1031 14:54:18.565430 31652 slave.cpp:4251] Received ping from \
> slave-observer(201)@172.17.0.3:46956 I1031 14:54:18.565668 31649 slave.cpp:1115] \
> Registered with master master@172.17.0.3:46956; given agent ID \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 I1031 14:54:18.565706 31649 fetcher.cpp:86] \
> Clearing fetcher cache I1031 14:54:18.565615 31651 master.cpp:5222] Registered \
> agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] \
> I1031 14:54:18.565855 31654 status_update_manager.cpp:184] Resuming sending status \
> updates I1031 14:54:18.565848 31655 replica.cpp:537] Replica received write request \
> for position 6 from __req_res__(3001)@172.17.0.3:46956 I1031 14:54:18.565982 31645 \
> hierarchical.cpp:485] Added agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 \
> (173b586c223f) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] \
> (allocated: {}) I1031 14:54:18.566078 31649 slave.cpp:1138] Checkpointing SlaveInfo \
> to '/tmp/MasterTest_OrphanTasksMultipleAgents_7SCiCN/meta/slaves/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1/slave.info'
>  I1031 14:54:18.566566 31655 leveldb.cpp:341] Persisting action (16 bytes) to \
> leveldb took 622375ns I1031 14:54:18.566586 31649 slave.cpp:1175] Forwarding total \
> oversubscribed resources {} I1031 14:54:18.566591 31655 replica.cpp:708] Persisted \
> action TRUNCATE at position 6 I1031 14:54:18.566735 31649 master.cpp:5621] Received \
> update of agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at \
> I1031 14:54:18.567229 31645 hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 in 1.19084ms I1031 14:54:18.567384 31648 \
> replica.cpp:691] Replica received learned notice for position 6 from @0.0.0.0:0 \
> I1031 14:54:18.567620 31645 hierarchical.cpp:555] Agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 (173b586c223f) updated with oversubscribed \
> resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], \
> allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I1031 \
> 14:54:18.567729 31642 master.cpp:6571] Sending 1 offers to framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.567814 31645 hierarchical.cpp:1694] No allocations performed I1031 \
> 14:54:18.567865 31645 hierarchical.cpp:1789] No inverse offers to send out! I1031 \
> 14:54:18.567997 31645 hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 in 290412ns I1031 14:54:18.568034 31648 \
> leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 580942ns I1031 \
> 14:54:18.568120 31648 leveldb.cpp:399] Deleting ~2 keys from leveldb took 49833ns \
> I1031 14:54:18.568147 31648 replica.cpp:708] Persisted action TRUNCATE at position \
> 6 I1031 14:54:18.568269 31655 sched.cpp:917] Scheduler::resourceOffers took \
> 118768ns I1031 14:54:18.570488 31646 master.cpp:3581] Processing ACCEPT call for \
> offers: [ 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-O1 ] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) for framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 I1031 \
> 14:54:18.570608 31646 master.cpp:3173] Authorizing framework principal \
> 'test-principal' to launch task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 W1031 \
> 14:54:18.573030 31657 validation.cpp:920] Executor 'default' for task \
> '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' uses less CPUs (None) than the minimum \
> required (0.01). Please update your executor, as this will be mandatory in future \
> releases. W1031 14:54:18.573073 31657 validation.cpp:932] Executor 'default' for \
> task '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' uses less memory (None) than the \
> minimum required (32MB). Please update your executor, as this will be mandatory in \
> future releases. I1031 14:54:18.573660 31657 master.cpp:8334] Adding task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 with resources cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 (173b586c223f) I1031 14:54:18.574072 31657 \
> master.cpp:4230] Launching task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 with resources \
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.574569 31651 slave.cpp:1547] Got assigned task \
> '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' for framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.575388 31651 \
> slave.cpp:1709] Launching task '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' for framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.576159 31651 \
> paths.cpp:536] Trying to chown \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_7SCiCN/slaves/5098f7d2-2044-4dcd-b97f-9bd \
> 7c3dd1e27-S1/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/fb01a7c6-1cf6-4ff9-b768-61ce927127bc' \
> to user 'mesos' I1031 14:54:18.584102 31651 slave.cpp:6307] Launching executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 with resources {} \
> in work directory '/tmp/MasterTest_OrphanTasksMultipleAgents_7SCiCN/slaves/5098f7d2- \
> 2044-4dcd-b97f-9bd7c3dd1e27-S1/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/fb01a7c6-1cf6-4ff9-b768-61ce927127bc'
>  I1031 14:54:18.587211 31651 exec.cpp:162] Version: 1.2.0
> I1031 14:54:18.587581 31650 exec.cpp:212] Executor started at: \
> executor(79)@172.17.0.3:46956 with pid 31623 I1031 14:54:18.588001 31651 \
> slave.cpp:2031] Queued task '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' for executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 \
> 14:54:18.588085 31651 slave.cpp:868] Successfully attached file \
> '/tmp/MasterTest_OrphanTasksMultipleAgents_7SCiCN/slaves/5098f7d2-2044-4dcd-b97f-9bd \
> 7c3dd1e27-S1/frameworks/5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000/executors/default/runs/fb01a7c6-1cf6-4ff9-b768-61ce927127bc'
>  I1031 14:54:18.588179 31651 slave.cpp:3305] Got registration for executor \
> 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from \
> executor(79)@172.17.0.3:46956 I1031 14:54:18.588629 31643 exec.cpp:237] Executor \
> registered on agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 I1031 14:54:18.588697 \
> 31643 exec.cpp:249] Executor::registered took 34326ns I1031 14:54:18.589377 31651 \
> slave.cpp:2247] Sending queued task '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' to \
> executor 'default' of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 at \
> executor(79)@172.17.0.3:46956 I1031 14:54:18.589785 31652 exec.cpp:324] Executor \
> asked to run task '11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0' I1031 14:54:18.589892 \
> 31652 exec.cpp:333] Executor::launchTask took 74900ns I1031 14:54:18.590060 31652 \
> exec.cpp:550] Executor sending status update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.590425 31649 \
> slave.cpp:3740] Handling status update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from \
> executor(79)@172.17.0.3:46956 I1031 14:54:18.591174 31652 \
> status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.591233 31652 \
> status_update_manager.cpp:500] Creating StatusUpdate stream for task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.591780 31652 \
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to the agent I1031 \
> 14:54:18.592180 31651 slave.cpp:4169] Forwarding the update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to master@172.17.0.3:46956 \
> I1031 14:54:18.592463 31651 slave.cpp:4063] Status update manager successfully \
> handled status update TASK_RUNNING (UUID: 4d1f38ad-684a-462f-ba03-4398f01694db) for \
> task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.592525 31651 \
> slave.cpp:4079] Sending acknowledgement for status update TASK_RUNNING (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 to \
> executor(79)@172.17.0.3:46956 I1031 14:54:18.592603 31647 master.cpp:5757] Status \
> update TASK_RUNNING (UUID: 4d1f38ad-684a-462f-ba03-4398f01694db) for task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 from agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.592679 31647 master.cpp:5819] Forwarding status \
> update TASK_RUNNING (UUID: 4d1f38ad-684a-462f-ba03-4398f01694db) for task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.592748 31649 exec.cpp:373] \
> Executor received status update acknowledgement \
> 4d1f38ad-684a-462f-ba03-4398f01694db for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.592947 31647 \
> master.cpp:7712] Updating the state of task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of \
> framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (latest state: TASK_RUNNING, \
> status update state: TASK_RUNNING) I1031 14:54:18.593291 31655 sched.cpp:1025] \
> Scheduler::statusUpdate took 135341ns I1031 14:54:18.594218 31644 master.cpp:4867] \
> Processing ACKNOWLEDGE call 4d1f38ad-684a-462f-ba03-4398f01694db for task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 (default) at \
> scheduler-60a2639c-70b4-4d13-83e6-f200a8b308f5@172.17.0.3:46956 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 I1031 14:54:18.594410 31644 \
> master.cpp:1097] Master terminating I1031 14:54:18.594658 31655 \
> status_update_manager.cpp:395] Received status update acknowledgement (UUID: \
> 4d1f38ad-684a-462f-ba03-4398f01694db) for task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 \
> of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 W1031 14:54:18.594576 31644 \
> master.cpp:7794] Removing task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 with resources \
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) in non-terminal state TASK_RUNNING I1031 14:54:18.594992 31650 \
> slave.cpp:3022] Status update manager successfully handled status update \
> acknowledgement (UUID: 4d1f38ad-684a-462f-ba03-4398f01694db) for task \
> 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.595250 31649 \
> hierarchical.cpp:517] Removed agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 I1031 \
> 14:54:18.595525 31644 master.cpp:7837] Removing executor 'default' with resources \
> {} of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) W1031 14:54:18.596063 31644 master.cpp:7794] Removing task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a with resources cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) in non-terminal state TASK_RUNNING I1031 14:54:18.596593 31649 \
> hierarchical.cpp:517] Removed agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 I1031 \
> 14:54:18.596689 31644 master.cpp:7837] Removing executor 'default' with resources \
> {} of framework 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.597661 31649 hierarchical.cpp:337] Removed framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 I1031 14:54:18.598047 31657 \
> slave.cpp:4297] Got exited event for master@172.17.0.3:46956 I1031 14:54:18.598114 \
> 31653 slave.cpp:4297] Got exited event for master@172.17.0.3:46956 W1031 \
> 14:54:18.598136 31653 slave.cpp:4302] Master disconnected! Waiting for a new master \
> to be elected W1031 14:54:18.598136 31657 slave.cpp:4302] Master disconnected! \
> Waiting for a new master to be elected I1031 14:54:18.604696 31623 cluster.cpp:158] \
> Creating default 'local' authorizer I1031 14:54:18.608245 31623 leveldb.cpp:174] \
> Opened db in 3.227023ms I1031 14:54:18.611130 31623 leveldb.cpp:181] Compacted db \
> in 2.848105ms I1031 14:54:18.611196 31623 leveldb.cpp:196] Created db iterator in \
> 23453ns I1031 14:54:18.611227 31623 leveldb.cpp:202] Seeked to beginning of db in \
> 16697ns I1031 14:54:18.611335 31623 leveldb.cpp:271] Iterated through 3 keys in the \
> db in 90684ns I1031 14:54:18.611428 31623 replica.cpp:776] Replica recovered with \
> log positions 5 -> 6 with 0 holes and 0 unlearned I1031 14:54:18.612046 31646 \
> recover.cpp:451] Starting replica recovery I1031 14:54:18.612493 31651 \
> recover.cpp:477] Replica is in VOTING status I1031 14:54:18.612758 31651 \
> recover.cpp:466] Recover process terminated I1031 14:54:18.614444 31654 \
> master.cpp:380] Master 5a14d27f-26b6-4697-9beb-0f36b3dcda4c (173b586c223f) started \
> on 172.17.0.3:46956 I1031 14:54:18.614476 31654 master.cpp:382] Flags at startup: \
> --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" \
> --allocation_interval="1secs" --allocator="HierarchicalDRF" \
> --authenticate_agents="true" --authenticate_frameworks="true" \
> --authenticate_http_frameworks="true" --authenticate_http_readonly="true" \
> --authenticate_http_readwrite="true" --authenticators="crammd5" \
> --authorizers="local" --credentials="/tmp/ClEWj4/credentials" \
> --framework_sorter="drf" --help="false" --hostname_lookup="true" \
> --http_authenticators="basic" --http_framework_authenticators="basic" \
> --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" \
> --logging_level="INFO" --max_agent_ping_timeouts="5" \
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" \
> --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" \
> --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="/mesos/mesos-1.2.0/_inst/share/mesos/webui" \
> --work_dir="/tmp/ClEWj4/master" --zk_session_timeout="10secs" I1031 14:54:18.615159 \
> 31654 master.cpp:432] Master only allowing authenticated frameworks to register \
> I1031 14:54:18.615186 31654 master.cpp:446] Master only allowing authenticated \
> agents to register I1031 14:54:18.615202 31654 master.cpp:459] Master only allowing \
> authenticated HTTP frameworks to register I1031 14:54:18.615221 31654 \
> credentials.hpp:37] Loading credentials for authentication from \
> '/tmp/ClEWj4/credentials' I1031 14:54:18.615653 31654 master.cpp:504] Using default \
> 'crammd5' authenticator I1031 14:54:18.615836 31654 http.cpp:887] Using default \
> 'basic' HTTP authenticator for realm 'mesos-master-readonly' I1031 14:54:18.616070 \
> 31654 http.cpp:887] Using default 'basic' HTTP authenticator for realm \
> 'mesos-master-readwrite' I1031 14:54:18.616211 31654 http.cpp:887] Using default \
> 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I1031 14:54:18.616320 \
> 31654 master.cpp:584] Authorization enabled I1031 14:54:18.616480 31649 \
> whitelist_watcher.cpp:77] No whitelist given I1031 14:54:18.616485 31651 \
> hierarchical.cpp:149] Initialized hierarchical allocator process I1031 \
> 14:54:18.619087 31652 master.cpp:2033] Elected as the leading master! I1031 \
> 14:54:18.619113 31652 master.cpp:1560] Recovering from registrar I1031 \
> 14:54:18.619220 31646 registrar.cpp:329] Recovering registrar I1031 14:54:18.619686 \
> 31651 log.cpp:553] Attempting to start the writer I1031 14:54:18.620842 31647 \
> replica.cpp:493] Replica received implicit promise request from \
> __req_res__(3002)@172.17.0.3:46956 with proposal 2 I1031 14:54:18.621428 31647 \
> leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 551908ns I1031 \
> 14:54:18.621451 31647 replica.cpp:342] Persisted promised to 2 I1031 \
> 14:54:18.622010 31650 coordinator.cpp:238] Coordinator attempting to fill missing \
> positions I1031 14:54:18.622259 31655 log.cpp:569] Writer started with ending \
> position 6 I1031 14:54:18.623313 31645 leveldb.cpp:436] Reading position from \
> leveldb took 59676ns I1031 14:54:18.623406 31645 leveldb.cpp:436] Reading position \
> from leveldb took 33374ns I1031 14:54:18.625212 31650 registrar.cpp:362] \
> Successfully fetched the registry (464B) in 5.854208ms I1031 14:54:18.625520 31650 \
> registrar.cpp:461] Applied 1 operations in 67195ns; attempting to update the \
> registry I1031 14:54:18.626541 31649 log.cpp:577] Attempting to append 503 bytes to \
> the log I1031 14:54:18.626691 31645 coordinator.cpp:348] Coordinator attempting to \
> write APPEND action at position 7 I1031 14:54:18.627703 31656 replica.cpp:537] \
> Replica received write request for position 7 from \
> __req_res__(3003)@172.17.0.3:46956 I1031 14:54:18.628237 31656 leveldb.cpp:341] \
> Persisting action (522 bytes) to leveldb took 484788ns I1031 14:54:18.628268 31656 \
> replica.cpp:708] Persisted action APPEND at position 7 I1031 14:54:18.629057 31648 \
> replica.cpp:691] Replica received learned notice for position 7 from @0.0.0.0:0 \
> I1031 14:54:18.629573 31648 leveldb.cpp:341] Persisting action (524 bytes) to \
> leveldb took 468946ns I1031 14:54:18.629606 31648 replica.cpp:708] Persisted action \
> APPEND at position 7 I1031 14:54:18.631556 31652 registrar.cpp:506] Successfully \
> updated the registry in 5.9648ms I1031 14:54:18.631827 31651 log.cpp:596] \
> Attempting to truncate the log to 7 I1031 14:54:18.631916 31652 registrar.cpp:392] \
> Successfully recovered registrar I1031 14:54:18.632025 31649 coordinator.cpp:348] \
> Coordinator attempting to write TRUNCATE action at position 8 I1031 14:54:18.632654 \
> 31656 replica.cpp:537] Replica received write request for position 8 from \
> __req_res__(3004)@172.17.0.3:46956 I1031 14:54:18.633050 31656 leveldb.cpp:341] \
> Persisting action (16 bytes) to leveldb took 359655ns I1031 14:54:18.633080 31656 \
> replica.cpp:708] Persisted action TRUNCATE at position 8 I1031 14:54:18.633361 \
> 31644 master.cpp:1676] Recovered 2 agents from the registry (464B); allowing 10mins \
> for agents to re-register I1031 14:54:18.633430 31650 hierarchical.cpp:176] \
> Skipping recovery of hierarchical allocator: nothing to recover I1031 \
> 14:54:18.633929 31655 replica.cpp:691] Replica received learned notice for position \
> 8 from @0.0.0.0:0 I1031 14:54:18.634366 31655 leveldb.cpp:341] Persisting action \
> (18 bytes) to leveldb took 371057ns I1031 14:54:18.634430 31655 leveldb.cpp:399] \
> Deleting ~2 keys from leveldb took 34917ns I1031 14:54:18.634454 31655 \
> replica.cpp:708] Persisted action TRUNCATE at position 8 I1031 14:54:18.635414 \
> 31657 slave.cpp:915] New master detected at master@172.17.0.3:46956 I1031 \
> 14:54:18.635432 31646 status_update_manager.cpp:177] Pausing sending status updates \
> I1031 14:54:18.635443 31657 slave.cpp:974] Authenticating with master \
> master@172.17.0.3:46956 I1031 14:54:18.635502 31646 slave.cpp:915] New master \
> detected at master@172.17.0.3:46956 I1031 14:54:18.635525 31646 slave.cpp:974] \
> Authenticating with master master@172.17.0.3:46956 I1031 14:54:18.635560 31657 \
> slave.cpp:985] Using default CRAM-MD5 authenticatee I1031 14:54:18.635598 31645 \
> status_update_manager.cpp:177] Pausing sending status updates I1031 14:54:18.635598 \
> 31646 slave.cpp:985] Using default CRAM-MD5 authenticatee I1031 14:54:18.635813 \
> 31657 slave.cpp:947] Detecting new master I1031 14:54:18.635885 31656 \
> authenticatee.cpp:121] Creating new client SASL connection I1031 14:54:18.636018 \
> 31649 authenticatee.cpp:121] Creating new client SASL connection I1031 \
> 14:54:18.636176 31646 slave.cpp:947] Detecting new master I1031 14:54:18.636258 \
> 31654 master.cpp:6742] Authenticating slave(199)@172.17.0.3:46956 I1031 \
> 14:54:18.636364 31650 authenticator.cpp:414] Starting authentication session for \
> crammd5-authenticatee(454)@172.17.0.3:46956 I1031 14:54:18.636493 31654 \
> master.cpp:6742] Authenticating slave(198)@172.17.0.3:46956 I1031 14:54:18.636574 \
> 31646 authenticator.cpp:98] Creating new server SASL connection I1031 \
> I1031 14:54:18.636772 31649 authenticatee.cpp:213] Received SASL authentication \
> mechanisms: CRAM-MD5 I1031 14:54:18.636802 31648 authenticator.cpp:98] Creating new \
> server SASL connection I1031 14:54:18.636842 31649 authenticatee.cpp:239] \
> Attempting to authenticate with mechanism 'CRAM-MD5' I1031 14:54:18.637020 31652 \
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I1031 \
> 14:54:18.637034 31648 authenticator.cpp:204] Received SASL authentication start \
> I1031 14:54:18.637053 31652 authenticatee.cpp:239] Attempting to authenticate with \
> mechanism 'CRAM-MD5' I1031 14:54:18.637095 31648 authenticator.cpp:326] \
> Authentication requires more steps I1031 14:54:18.637167 31652 \
> authenticator.cpp:204] Received SASL authentication start I1031 14:54:18.637181 \
> 31648 authenticatee.cpp:259] Received SASL authentication step I1031 \
> 14:54:18.637217 31652 authenticator.cpp:326] Authentication requires more steps \
> I1031 14:54:18.637265 31648 authenticator.cpp:232] Received SASL authentication \
> step I1031 14:54:18.637292 31648 auxprop.cpp:109] Request to lookup properties for \
> user: 'test-principal' realm: '173b586c223f' server FQDN: '173b586c223f' \
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: false  I1031 14:54:18.637308 31648 auxprop.cpp:181] Looking \
> up auxiliary property '*userPassword' I1031 14:54:18.637310 31652 \
> authenticatee.cpp:259] Received SASL authentication step I1031 14:54:18.637362 \
> 31648 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1031 \
> 14:54:18.637399 31648 auxprop.cpp:109] Request to lookup properties for user: \
> 'test-principal' realm: '173b586c223f' server FQDN: '173b586c223f' \
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: true  I1031 14:54:18.637419 31648 auxprop.cpp:131] Skipping \
> auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1031 \
> 14:54:18.637437 31648 auxprop.cpp:131] Skipping auxiliary property \
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1031 14:54:18.637454 \
> 31655 authenticator.cpp:232] Received SASL authentication step I1031 \
> 14:54:18.637461 31648 authenticator.cpp:318] Authentication success I1031 \
> 14:54:18.637483 31655 auxprop.cpp:109] Request to lookup properties for user: \
> 'test-principal' realm: '173b586c223f' server FQDN: '173b586c223f' \
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false \
> SASL_AUXPROP_AUTHZID: false  I1031 14:54:18.637501 31655 auxprop.cpp:181] Looking \
> up auxiliary property '*userPassword' I1031 14:54:18.637522 31655 auxprop.cpp:181] \
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1031 14:54:18.637549 31655 \
> auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: \
> '173b586c223f' server FQDN: '173b586c223f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false \
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true  I1031 14:54:18.637575 \
> 31655 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since \
> SASL_AUXPROP_AUTHZID == true I1031 14:54:18.637585 31655 auxprop.cpp:131] Skipping \
> auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true \
> I1031 14:54:18.637603 31655 authenticator.cpp:318] Authentication success I1031 \
> 14:54:18.637689 31643 authenticator.cpp:432] Authentication session cleanup for \
> crammd5-authenticatee(454)@172.17.0.3:46956 I1031 14:54:18.637704 31649 \
> authenticatee.cpp:299] Authentication success I1031 14:54:18.637552 31652 \
> authenticatee.cpp:299] Authentication success I1031 14:54:18.637948 31643 \
> authenticator.cpp:432] Authentication session cleanup for \
> crammd5-authenticatee(453)@172.17.0.3:46956 I1031 14:54:18.638047 31645 \
> slave.cpp:1069] Successfully authenticated with master master@172.17.0.3:46956 \
> I1031 14:54:18.638206 31656 slave.cpp:1069] Successfully authenticated with master \
> master@172.17.0.3:46956 I1031 14:54:18.638486 31656 slave.cpp:1483] Will retry \
> registration in 7.380044ms if necessary I1031 14:54:18.638504 31645 slave.cpp:1483] \
> Will retry registration in 2.286536ms if necessary I1031 14:54:18.637601 31654 \
> master.cpp:6772] Successfully authenticated principal 'test-principal' at \
> slave(199)@172.17.0.3:46956 I1031 14:54:18.638775 31654 master.cpp:6772] \
> Successfully authenticated principal 'test-principal' at \
> slave(198)@172.17.0.3:46956 I1031 14:54:18.639214 31654 master.cpp:5370] \
> Re-registering agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at \
> slave(199)@172.17.0.3:46956 (173b586c223f) I1031 14:54:18.639966 31644 \
> registrar.cpp:461] Applied 1 operations in 54895ns; attempting to update the \
> registry I1031 14:54:18.640280 31654 master.cpp:5370] Re-registering agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.640707 31644 log.cpp:577] Attempting to append 503 \
> bytes to the log I1031 14:54:18.640811 31657 coordinator.cpp:348] Coordinator \
> attempting to write APPEND action at position 9 I1031 14:54:18.641525 31652 \
> replica.cpp:537] Replica received write request for position 9 from \
> __req_res__(3005)@172.17.0.3:46956 I1031 14:54:18.641760 31652 leveldb.cpp:341] \
> Persisting action (522 bytes) to leveldb took 194719ns I1031 14:54:18.641788 31652 \
> replica.cpp:708] Persisted action APPEND at position 9 I1031 14:54:18.642148 31652 \
> slave.cpp:1483] Will retry registration in 31.9918ms if necessary I1031 \
> 14:54:18.642640 31646 master.cpp:5363] Ignoring re-register agent message from \
> agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) as readmission is already in progress I1031 14:54:18.642675 31642 \
> replica.cpp:691] Replica received learned notice for position 9 from @0.0.0.0:0 \
> I1031 14:54:18.643157 31642 leveldb.cpp:341] Persisting action (524 bytes) to \
> leveldb took 444580ns I1031 14:54:18.643191 31642 replica.cpp:708] Persisted action \
> APPEND at position 9 I1031 14:54:18.645174 31644 registrar.cpp:506] Successfully \
> updated the registry in 5.126912ms I1031 14:54:18.645500 31652 log.cpp:596] \
> Attempting to truncate the log to 9 I1031 14:54:18.645648 31654 \
> coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 10 \
> I1031 14:54:18.645874 31644 registrar.cpp:461] Applied 1 operations in 66647ns; \
> attempting to update the registry I1031 14:54:18.646440 31657 master.cpp:8334] \
> Adding task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 with resources cpus(*):2; \
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 (173b586c223f) I1031 14:54:18.646606 31651 \
> replica.cpp:537] Replica received write request for position 10 from \
> __req_res__(3006)@172.17.0.3:46956 W1031 14:54:18.646946 31657 master.cpp:7414] \
> Possibly orphaned task 11a3e383-b8f4-4ee4-a2c6-a78b8b7507a0 of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 running on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.647025 31651 leveldb.cpp:341] Persisting action (16 \
> bytes) to leveldb took 369772ns I1031 14:54:18.647066 31651 replica.cpp:708] \
> Persisted action TRUNCATE at position 10 I1031 14:54:18.647284 31657 \
> master.cpp:5466] Re-registered agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at \
> slave(199)@172.17.0.3:46956 (173b586c223f) with cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] I1031 14:54:18.647390 31650 slave.cpp:1483] \
> Will retry registration in 12.331401ms if necessary I1031 14:54:18.647438 31657 \
> master.cpp:5560] Sending updated checkpointed resources {} to agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.647495 31650 slave.cpp:4251] Received ping from \
> slave-observer(202)@172.17.0.3:46956 I1031 14:54:18.647753 31650 slave.cpp:1217] \
> Re-registered with master master@172.17.0.3:46956 I1031 14:54:18.647744 31643 \
> hierarchical.cpp:485] Added agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 \
> (173b586c223f) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] \
> (allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I1031 \
> 14:54:18.647841 31650 slave.cpp:1253] Forwarding total oversubscribed resources {} \
> I1031 14:54:18.647847 31647 status_update_manager.cpp:184] Resuming sending status \
> updates I1031 14:54:18.647883 31657 master.cpp:5301] Re-registering agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.647933 31643 hierarchical.cpp:1694] No allocations \
> performed I1031 14:54:18.647969 31650 slave.cpp:2807] Ignoring new checkpointed \
> resources identical to the current version: {} I1031 14:54:18.648167 31643 \
> hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 in 364483ns I1031 14:54:18.648221 31657 \
> master.cpp:5560] Sending updated checkpointed resources {} to agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) W1031 14:54:18.648299 31651 slave.cpp:1234] Already re-registered \
> with master master@172.17.0.3:46956 I1031 14:54:18.648331 31651 slave.cpp:1253] \
> Forwarding total oversubscribed resources {} I1031 14:54:18.648439 31657 \
> master.cpp:5621] Received update of agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 \
> at slave(199)@172.17.0.3:46956 (173b586c223f) with total oversubscribed resources \
> {} I1031 14:54:18.648448 31656 replica.cpp:691] Replica received learned notice for \
> position 10 from @0.0.0.0:0 I1031 14:54:18.648525 31651 slave.cpp:2807] Ignoring \
> new checkpointed resources identical to the current version: {} I1031 \
> 14:54:18.648795 31657 master.cpp:5621] Received update of agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 at slave(199)@172.17.0.3:46956 \
> (173b586c223f) with total oversubscribed resources {} I1031 14:54:18.648811 31651 \
> hierarchical.cpp:555] Agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 (173b586c223f) \
> updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000]) I1031 14:54:18.648872 31656 leveldb.cpp:341] \
> Persisting action (18 bytes) to leveldb took 381171ns I1031 14:54:18.648941 31656 \
> leveldb.cpp:399] Deleting ~2 keys from leveldb took 40884ns I1031 14:54:18.648985 \
> 31656 replica.cpp:708] Persisted action TRUNCATE at position 10 I1031 \
> 14:54:18.649085 31651 hierarchical.cpp:1694] No allocations performed I1031 \
> 14:54:18.649155 31651 hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 in 267700ns I1031 14:54:18.649305 31651 \
> hierarchical.cpp:555] Agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 (173b586c223f) \
> updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000]) I1031 14:54:18.649469 31651 \
> hierarchical.cpp:1694] No allocations performed I1031 14:54:18.649554 31651 \
> hierarchical.cpp:1309] Performed allocation for agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S1 in 195355ns I1031 14:54:18.650046 31643 \
> log.cpp:577] Attempting to append 503 bytes to the log I1031 14:54:18.650197 31653 \
> coordinator.cpp:348] Coordinator attempting to write APPEND action at position 11 \
> I1031 14:54:18.650496 31648 process.cpp:3570] Handling HTTP event for process \
> 'master' with path: '/master/state' I1031 14:54:18.651095 31657 replica.cpp:537] \
> Replica received write request for position 11 from \
> __req_res__(3007)@172.17.0.3:46956 I1031 14:54:18.651302 31657 leveldb.cpp:341] \
> Persisting action (522 bytes) to leveldb took 160039ns I1031 14:54:18.651340 31657 \
> replica.cpp:708] Persisted action APPEND at position 11 I1031 14:54:18.651604 31651 \
> http.cpp:391] HTTP GET for /master/state from 172.17.0.3:35755 I1031 \
> 14:54:18.652230 31656 replica.cpp:691] Replica received learned notice for position \
> 11 from @0.0.0.0:0 I1031 14:54:18.652693 31656 leveldb.cpp:341] Persisting action \
> (524 bytes) to leveldb took 420455ns I1031 14:54:18.652725 31656 replica.cpp:708] \
> Persisted action APPEND at position 11 I1031 14:54:18.654693 31648 \
> registrar.cpp:506] Successfully updated the registry in 8.75392ms I1031 \
> 14:54:18.655004 31650 log.cpp:596] Attempting to truncate the log to 11 I1031 \
> 14:54:18.655267 31656 coordinator.cpp:348] Coordinator attempting to write TRUNCATE \
> action at position 12 I1031 14:54:18.655925 31645 master.cpp:8334] Adding task \
> 3d00a1fe-59e4-42cf-a231-df3a06aecc3a with resources cpus(*):2; mem(*):1024; \
> disk(*):1024; ports(*):[31000-32000] on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 (173b586c223f) I1031 14:54:18.656440 31647 \
> replica.cpp:537] Replica received write request for position 12 from \
> __req_res__(3008)@172.17.0.3:46956 W1031 14:54:18.656488 31645 master.cpp:7414] \
> Possibly orphaned task 3d00a1fe-59e4-42cf-a231-df3a06aecc3a of framework \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-0000 running on agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.656636 31649 slave.cpp:4251] Received ping from \
> slave-observer(203)@172.17.0.3:46956 I1031 14:54:18.656883 31647 leveldb.cpp:341] \
> Persisting action (16 bytes) to leveldb took 388466ns I1031 14:54:18.656944 31651 \
> slave.cpp:1217] Re-registered with master master@172.17.0.3:46956 I1031 \
> 14:54:18.656944 31647 replica.cpp:708] Persisted action TRUNCATE at position 12 \
> I1031 14:54:18.656857 31645 master.cpp:5466] Re-registered agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] \
> I1031 14:54:18.657088 31645 master.cpp:5560] Sending updated checkpointed resources \
> {} to agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
> (173b586c223f) I1031 14:54:18.657121 31657 status_update_manager.cpp:184] Resuming \
> sending status updates I1031 14:54:18.657127 31651 slave.cpp:1253] Forwarding total \
> oversubscribed resources {} I1031 14:54:18.657199 31644 hierarchical.cpp:485] Added \
> agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 (173b586c223f) with cpus(*):2; \
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: cpus(*):2; \
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I1031 14:54:18.657316 31651 \
> slave.cpp:2807] Ignoring new checkpointed resources identical to the current \
> version: {} I1031 14:54:18.657330 31644 hierarchical.cpp:1694] No allocations \
> performed I1031 14:54:18.657398 31644 hierarchical.cpp:1309] Performed allocation \
> for agent 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 in 153893ns I1031 14:54:18.657395 \
> 31645 master.cpp:5621] Received update of agent \
> 5098f7d2-2044-4dcd-b97f-9bd7c3dd1e27-S0 at slave(198)@172.17.0.3:46956 \
>                 (173b586c223f) with total oversubscribed resources {}
> ../../src/tests/master_tests.cpp:3074: Failure
> Value of: orphanTasks.values.size()
> Actual: 1
> Expected: 2u
> Which is: 2
> {code}



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


[prev in list] [next in list] [prev in thread] [next in thread]