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

Guangya Liu commented on MESOS-6308:
------------------------------------

This is a race issue in tear down and calculating the dominant share metrics, 
this can be happened with following sequence with 
{{PartitionTest.DisconnectedFramework}}:

1) {{driver.stop()}} will send a {{TEARDOWN}} request to master which will 
trigger {{removeFramework}} in allocator. 

2) The {{PartitionTest.DisconnectedFramework}} construct the {{Metrics}} object 
with following code, and at this time the default role was not removed, and the 
{{calculateShare}} will be in queue to calculate the dominant share for default 
role.

{code}
JSON::Object stats = Metrics();
{code}

3) The remove framework in master continues and it call allocator to remove 
framework. As there is only one framework under star role, so the 
{{removeFramework}} will call {{roleSorter->remove(role);}} to remove the role 
and its related allocations, the race will be here, take a look at the API of 
{{remove}} in sorter.cpp.

{code}
void DRFSorter::remove(const string& name)
{
  set<Client, DRFComparator>::iterator it = find(name);

  if (it != clients.end()) {
    clients.erase(it);
  }
 
  allocations.erase(name);
  weights.erase(name);

  <<<<<<<<<<<<<<<<< `calculateShare` was triggered here to  calculate the 
dominant share for default role, but at this time, the default role allocation 
was now removed and  `calculateShare` will report CHECK FAIL. It is very 
difficult to reproduce this, that's why I run test for more than 1 hour to 
reproduce this.

  if (metrics.isSome()) {
    metrics->remove(name);
  }
}
{code}

I updated the code of {{DRFSorter::remove(const string& name)}} a bit by adding 
a {{os::sleep(Seconds(1));}} between {{allocations.erase(name);}} and 
{{metrics->remove(name);}} as following:

{code}
--- a/src/master/allocator/sorter/drf/sorter.cpp
+++ b/src/master/allocator/sorter/drf/sorter.cpp
@@ -29,6 +29,8 @@
 #include <stout/foreach.hpp>
 #include <stout/option.hpp>

+#include <stout/os.hpp>
+
 #include "logging/logging.hpp"

 #include "master/allocator/sorter/drf/sorter.hpp"
@@ -110,6 +112,8 @@ void DRFSorter::remove(const string& name)
   allocations.erase(name);
   weights.erase(name);

+  os::sleep(Seconds(1));
+
   if (metrics.isSome()) {
     metrics->remove(name);
   }
{code}

Then re-run the test {{PartitionTest.DisconnectedFramework}}, it will be failed 
every time and CHECK FAIL at the same place:
{code}
[ RUN      ] PartitionTest.DisconnectedFramework
I1010 15:43:46.022001 257765376 exec.cpp:162] Version: 1.1.0
I1010 15:43:46.025545 259375104 exec.cpp:237] Executor registered on agent 
5bc85014-3fab-459f-9d85-8b47a06e27d0-S0
Received SUBSCRIBED event
Subscribed executor on 192.168.56.1
Received LAUNCH event
Starting task 51f3e50a-e561-407b-8ee4-65f163d65bd7
/Users/gyliu/git/mesos/build/src/mesos-containerizer launch 
--command="{"shell":true,"value":"sleep 60"}" --help="false"
Forked command at 93007
F1010 15:43:50.094323 407199744 sorter.cpp:454] Check failed: contains(name)
*** Check failure stack trace: ***
    @        0x1119b91ca  google::LogMessage::Fail()
    @        0x1119b8157  google::LogMessage::SendToLog()
    @        0x1119b8e7a  google::LogMessage::Flush()
    @        0x1119bfce8  google::LogMessageFatal::~LogMessageFatal()
    @        0x1119b9605  google::LogMessageFatal::~LogMessageFatal()
    @        0x10fa0bd18  
mesos::internal::master::allocator::DRFSorter::calculateShare()
    @        0x10fa05c5e  
mesos::internal::master::allocator::Metrics::add()::$_0::operator()()
    @        0x10fa09232  
_ZZN7process8internal8DispatchIdEclIRKZN5mesos8internal6master9allocator7Metrics3addERKNSt3__112basic_stringIcNS9_11char_traitsIcEENS9_9allocatorIcEEEEE3$_0EENS_6FutureIdEERKNS_4UPIDEOT_ENKUlPNS_11ProcessBaseEE_clEST_
    @        0x10fa091f0  
_ZNSt3__128__invoke_void_return_wrapperIvE6__callIJRZN7process8internal8DispatchIdEclIRKZN5mesos8internal6master9allocator7Metrics3addERKNS_12basic_stringIcNS_11char_traitsIcEENS_9allocatorIcEEEEE3$_0EENS3_6FutureIdEERKNS3_4UPIDEOT_EUlPNS3_11ProcessBaseEE_SW_EEEvDpOT_
    @        0x10fa08e9c  
_ZNSt3__110__function6__funcIZN7process8internal8DispatchIdEclIRKZN5mesos8internal6master9allocator7Metrics3addERKNS_12basic_stringIcNS_11char_traitsIcEENS_9allocatorIcEEEEE3$_0EENS2_6FutureIdEERKNS2_4UPIDEOT_EUlPNS2_11ProcessBaseEE_NSF_ISW_EEFvSV_EEclEOSV_
    @        0x111897acf  std::__1::function<>::operator()()
    @        0x1118684ff  process::ProcessBase::visit()
    @        0x1118cc18e  process::DispatchEvent::visit()
    @        0x109a75431  process::ProcessBase::serve()
    @        0x1118651d1  process::ProcessManager::resume()
    @        0x111870cc6  
process::ProcessManager::init_threads()::$_1::operator()()
    @        0x111870969  
_ZNSt3__114__thread_proxyINS_5tupleIJZN7process14ProcessManager12init_threadsEvE3$_1EEEEEPvS6_
    @     0x7fff859fa05a  _pthread_body
    @     0x7fff859f9fd7  _pthread_start
    @     0x7fff859f73ed  thread_start
{code}

> CHECK failure in DRF sorter.
> ----------------------------
>
>                 Key: MESOS-6308
>                 URL: https://issues.apache.org/jira/browse/MESOS-6308
>             Project: Mesos
>          Issue Type: Bug
>            Reporter: Jie Yu
>            Assignee: Guangya Liu
>
> Saw this CHECK failed in our internal CI:
> https://github.com/apache/mesos/blob/master/src/master/allocator/sorter/drf/sorter.cpp#L450
> {noformat}
> [03:08:28] :   [Step 10/10] [ RUN      ] PartitionTest.DisconnectedFramework
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.200443   577 cluster.cpp:158] 
> Creating default 'local' authorizer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.206408   577 leveldb.cpp:174] 
> Opened db in 5.827159ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208127   577 leveldb.cpp:181] 
> Compacted db in 1.697508ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208150   577 leveldb.cpp:196] 
> Created db iterator in 5756ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208160   577 leveldb.cpp:202] 
> Seeked to beginning of db in 1483ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208168   577 leveldb.cpp:271] 
> Iterated through 0 keys in the db in 1101ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208184   577 replica.cpp:776] 
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208452   591 recover.cpp:451] 
> Starting replica recovery
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.208664   596 recover.cpp:477] 
> Replica is in EMPTY status
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209079   591 replica.cpp:673] 
> Replica in EMPTY status received a broadcasted recover request from 
> __req_res__(3666)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209203   593 recover.cpp:197] 
> Received a recover response from a replica in EMPTY status
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209394   598 recover.cpp:568] 
> Updating replica status to STARTING
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209473   598 master.cpp:380] 
> Master dd11d4ad-2087-4324-99ef-873e83ff09a1 (ip-172-30-2-234.mesosphere.io) 
> started on 172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209489   598 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/7rr0oB/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="/usr/local/share/mesos/webui" --work_dir="/tmp/7rr0oB/master" 
> --zk_session_timeout="10secs"
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209692   598 master.cpp:432] 
> Master only allowing authenticated frameworks to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209699   598 master.cpp:446] 
> Master only allowing authenticated agents to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209704   598 master.cpp:459] 
> Master only allowing authenticated HTTP frameworks to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209709   598 credentials.hpp:37] 
> Loading credentials for authentication from '/tmp/7rr0oB/credentials'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209810   598 master.cpp:504] Using 
> default 'crammd5' authenticator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209853   598 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209897   598 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209940   598 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.209962   598 master.cpp:584] 
> Authorization enabled
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210086   595 hierarchical.cpp:149] 
> Initialized hierarchical allocator process
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210095   591 
> whitelist_watcher.cpp:77] No whitelist given
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210736   597 master.cpp:2013] 
> Elected as the leading master!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210749   597 master.cpp:1560] 
> Recovering from registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210803   591 registrar.cpp:329] 
> Recovering registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210960   596 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.485184ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.210978   596 replica.cpp:320] 
> Persisted replica status to STARTING
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.211027   596 recover.cpp:477] 
> Replica is in STARTING status
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.211406   594 replica.cpp:673] 
> Replica in STARTING status received a broadcasted recover request from 
> __req_res__(3667)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.211513   595 recover.cpp:197] 
> Received a recover response from a replica in STARTING status
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.211684   595 recover.cpp:568] 
> Updating replica status to VOTING
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213109   592 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.372466ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213126   592 replica.cpp:320] 
> Persisted replica status to VOTING
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213166   592 recover.cpp:582] 
> Successfully joined the Paxos group
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213232   592 recover.cpp:466] 
> Recover process terminated
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213410   597 log.cpp:553] 
> Attempting to start the writer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.213906   594 replica.cpp:493] 
> Replica received implicit promise request from 
> __req_res__(3668)@172.30.2.234:37300 with proposal 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.215339   594 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.405866ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.215356   594 replica.cpp:342] 
> Persisted promised to 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.215672   594 coordinator.cpp:238] 
> Coordinator attempting to fill missing positions
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.216145   597 replica.cpp:388] 
> Replica received explicit promise request from 
> __req_res__(3669)@172.30.2.234:37300 for position 0 with proposal 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.217648   597 leveldb.cpp:341] 
> Persisting action (8 bytes) to leveldb took 1.472079ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.217666   597 replica.cpp:708] 
> Persisted action NOP at position 0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.218133   596 replica.cpp:537] 
> Replica received write request for position 0 from 
> __req_res__(3670)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.218168   596 leveldb.cpp:436] 
> Reading position from leveldb took 14053ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.219609   596 leveldb.cpp:341] 
> Persisting action (14 bytes) to leveldb took 1.421675ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.219625   596 replica.cpp:708] 
> Persisted action NOP at position 0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.219842   591 replica.cpp:691] 
> Replica received learned notice for position 0 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.221186   591 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.318296ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.221204   591 replica.cpp:708] 
> Persisted action NOP at position 0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.221410   592 log.cpp:569] Writer 
> started with ending position 0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.221770   596 leveldb.cpp:436] 
> Reading position from leveldb took 12199ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.222019   598 registrar.cpp:362] 
> Successfully fetched the registry (0B) in 11.19104ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.222064   598 registrar.cpp:461] 
> Applied 1 operations in 5462ns; attempting to update the registry
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.222260   594 log.cpp:577] 
> Attempting to append 209 bytes to the log
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.222307   594 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.222592   596 replica.cpp:537] 
> Replica received write request for position 1 from 
> __req_res__(3671)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.223984   596 leveldb.cpp:341] 
> Persisting action (228 bytes) to leveldb took 1.370525ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.224001   596 replica.cpp:708] 
> Persisted action APPEND at position 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.224231   594 replica.cpp:691] 
> Replica received learned notice for position 1 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.225666   594 leveldb.cpp:341] 
> Persisting action (230 bytes) to leveldb took 1.412011ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.225683   594 replica.cpp:708] 
> Persisted action APPEND at position 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.225906   595 registrar.cpp:506] 
> Successfully updated the registry in 3.81696ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.225975   591 log.cpp:596] 
> Attempting to truncate the log to 1
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.225977   595 registrar.cpp:392] 
> Successfully recovered registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.226027   591 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.226155   593 master.cpp:1676] 
> Recovered 0 agents from the registry (170B); allowing 10mins for agents to 
> re-register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.226181   591 hierarchical.cpp:176] 
> Skipping recovery of hierarchical allocator: nothing to recover
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.226425   592 replica.cpp:537] 
> Replica received write request for position 2 from 
> __req_res__(3672)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.227835   592 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.38578ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.227852   592 replica.cpp:708] 
> Persisted action TRUNCATE at position 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.228093   597 replica.cpp:691] 
> Replica received learned notice for position 2 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.229463   597 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.350511ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.229497   597 leveldb.cpp:399] 
> Deleting ~1 keys from leveldb took 15764ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.229506   597 replica.cpp:708] 
> Persisted action TRUNCATE at position 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.231326   577 
> containerizer.cpp:227] Using isolation: 
> posix/cpu,posix/mem,filesystem/posix,network/cni
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.236002   577 
> linux_launcher.cpp:150] Using /sys/fs/cgroup/freezer as the freezer hierarchy 
> for the Linux launcher
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.236968   577 cluster.cpp:435] 
> Creating default 'local' authorizer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237505   597 slave.cpp:208] Mesos 
> agent started on (261)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237517   597 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="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/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="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/fetch"
>  --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" 
> --gc_disk_headroom="0.1" --hadoop_home="" --help="true" 
> --hostname_lookup="true" --http_authenticators="basic" 
> --http_command_executor="false" 
> --http_credentials="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/http_credentials"
>  --image_provisioner_backend="copy" --initialize_driver_logging="true" 
> --isolation="posix/cpu,posix/mem" --launcher="linux" 
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" 
> --logbufsecs="0" --logging_level="INFO" 
> --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="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep"
>  --sandbox_directory="/mnt/mesos/sandbox" --strict="true" 
> --switch_user="true" --systemd_enable_support="true" 
> --systemd_runtime_directory="/run/systemd/system" --version="false" 
> --work_dir="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv"
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237741   597 credentials.hpp:86] 
> Loading credential for authentication from 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/credential'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237829   597 slave.cpp:346] Agent 
> using credential for: test-principal
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237843   597 credentials.hpp:37] 
> Loading credentials for authentication from 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/http_credentials'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237927   597 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.237970   597 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238199   577 sched.cpp:226] 
> Version: 1.1.0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238312   597 slave.cpp:533] Agent 
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238340   597 slave.cpp:541] Agent 
> attributes: [  ]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238346   597 slave.cpp:546] Agent 
> hostname: ip-172-30-2-234.mesosphere.io
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238438   598 sched.cpp:330] New 
> master detected at master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238467   598 sched.cpp:396] 
> Authenticating with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238476   598 sched.cpp:403] Using 
> default CRAM-MD5 authenticatee
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238615   596 
> authenticatee.cpp:121] Creating new client SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238845   597 state.cpp:57] 
> Recovering state from 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/meta'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238888   594 master.cpp:6634] 
> Authenticating 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238963   596 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(586)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.238982   591 
> status_update_manager.cpp:203] Recovering status update manager
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239024   598 authenticator.cpp:98] 
> Creating new server SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239060   596 
> containerizer.cpp:581] Recovering containerizer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239208   598 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239225   598 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239295   598 
> authenticator.cpp:204] Received SASL authentication start
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239331   598 
> authenticator.cpp:326] Authentication requires more steps
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239364   598 
> authenticatee.cpp:259] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239406   598 
> authenticator.cpp:232] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239421   598 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239428   598 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239437   598 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239445   598 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239451   598 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239456   598 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239466   598 
> authenticator.cpp:318] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239506   598 
> authenticatee.cpp:299] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239523   594 master.cpp:6664] 
> Successfully authenticated principal 'test-principal' at 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239545   591 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(586)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239696   598 sched.cpp:502] 
> Successfully authenticated with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239713   598 sched.cpp:820] 
> Sending SUBSCRIBE call to master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239778   598 sched.cpp:853] Will 
> retry registration in 1.739673627secs if necessary
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239830   597 master.cpp:2587] 
> Received SUBSCRIBE call for framework 'default' at 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239848   597 master.cpp:2049] 
> Authorizing framework principal 'test-principal' to receive offers for role 
> '*'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.239965   597 master.cpp:2663] 
> Subscribing framework default with checkpointing disabled and capabilities [  
> ]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240101   597 sched.cpp:743] 
> Framework registered with dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240115   594 hierarchical.cpp:275] 
> Added framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240149   597 sched.cpp:757] 
> Scheduler::registered took 29833ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240162   594 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240175   594 
> hierarchical.cpp:1789] No inverse offers to send out!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240195   594 
> hierarchical.cpp:1286] Performed allocation for 0 agents in 45179ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240322   595 provisioner.cpp:253] 
> Provisioner recovery complete
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240545   595 slave.cpp:5256] 
> Finished recovery
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240758   595 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240846   597 slave.cpp:915] New 
> master detected at master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240864   597 slave.cpp:974] 
> Authenticating with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240860   594 
> status_update_manager.cpp:177] Pausing sending status updates
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240875   597 slave.cpp:985] Using 
> default CRAM-MD5 authenticatee
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240911   597 slave.cpp:947] 
> Detecting new master
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240933   595 
> authenticatee.cpp:121] Creating new client SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.240953   597 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241107   595 master.cpp:6634] 
> Authenticating slave(261)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241161   595 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(587)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241225   595 authenticator.cpp:98] 
> Creating new server SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241406   595 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241427   595 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241490   593 
> authenticator.cpp:204] Received SASL authentication start
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241525   593 
> authenticator.cpp:326] Authentication requires more steps
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241561   593 
> authenticatee.cpp:259] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241593   593 
> authenticator.cpp:232] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241611   593 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241623   593 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241636   593 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241643   593 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241649   593 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241654   593 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241663   593 
> authenticator.cpp:318] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241700   593 
> authenticatee.cpp:299] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241713   591 master.cpp:6664] 
> Successfully authenticated principal 'test-principal' at 
> slave(261)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241729   593 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(587)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241821   591 slave.cpp:1069] 
> Successfully authenticated with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241890   591 slave.cpp:1475] Will 
> retry registration in 10.410698ms if necessary
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.241946   598 master.cpp:5074] 
> Registering agent at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io) with id 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.242053   598 registrar.cpp:461] 
> Applied 1 operations in 11436ns; attempting to update the registry
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.242274   591 log.cpp:577] 
> Attempting to append 395 bytes to the log
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.242337   593 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 3
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.242611   598 replica.cpp:537] 
> Replica received write request for position 3 from 
> __req_res__(3673)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.244024   598 leveldb.cpp:341] 
> Persisting action (414 bytes) to leveldb took 1.391166ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.244042   598 replica.cpp:708] 
> Persisted action APPEND at position 3
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.244272   596 replica.cpp:691] 
> Replica received learned notice for position 3 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.245693   596 leveldb.cpp:341] 
> Persisting action (416 bytes) to leveldb took 1.399878ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.245712   596 replica.cpp:708] 
> Persisted action APPEND at position 3
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246021   594 registrar.cpp:506] 
> Successfully updated the registry in 3.94496ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246057   597 log.cpp:596] 
> Attempting to truncate the log to 3
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246176   594 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 4
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246289   598 slave.cpp:4108] 
> Received ping from slave-observer(262)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246314   596 master.cpp:5145] 
> Registered agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) with cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246345   598 slave.cpp:1115] 
> Registered with master master@172.30.2.234:37300; given agent ID 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246382   598 fetcher.cpp:86] 
> Clearing fetcher cache
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246388   595 hierarchical.cpp:485] 
> Added agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 
> (ip-172-30-2-234.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; 
> ports(*):[31000-32000] (allocated: {})
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246467   591 
> status_update_manager.cpp:184] Resuming sending status updates
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246629   598 slave.cpp:1138] 
> Checkpointing SlaveInfo to 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/meta/slaves/dd11d4ad-2087-4324-99ef-873e83ff09a1-S0/slave.info'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246631   595 
> hierarchical.cpp:1789] No inverse offers to send out!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246677   595 
> hierarchical.cpp:1309] Performed allocation for agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 in 260907ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246726   596 master.cpp:6463] 
> Sending 1 offers to framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 
> (default) at scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246810   598 slave.cpp:1175] 
> Forwarding total oversubscribed resources {}
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246868   598 master.cpp:5542] 
> Received update of agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) with total 
> oversubscribed resources {}
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.246930   592 sched.cpp:917] 
> Scheduler::resourceOffers took 43738ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247004   598 replica.cpp:537] 
> Replica received write request for position 4 from 
> __req_res__(3674)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247021   597 hierarchical.cpp:555] 
> Agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 (ip-172-30-2-234.mesosphere.io) 
> updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; 
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; 
> disk(*):1024; ports(*):[31000-32000])
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247068   597 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247082   597 
> hierarchical.cpp:1789] No inverse offers to send out!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247104   597 
> hierarchical.cpp:1309] Performed allocation for agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 in 57331ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247540   596 master.cpp:3521] 
> Processing ACCEPT call for offers: [ dd11d4ad-2087-4324-99ef-873e83ff09a1-O0 
> ] on agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) for framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.247570   596 master.cpp:3143] 
> Authorizing framework principal 'test-principal' to launch task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248034   593 master.cpp:8206] 
> Adding task b4aadf16-5d8e-4c62-819e-e3c60b46a606 with resources cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248086   593 master.cpp:4153] 
> Launching task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300 with 
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on 
> agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248325   592 slave.cpp:1539] Got 
> assigned task 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' for framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248373   598 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.346221ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248391   598 replica.cpp:708] 
> Persisted action TRUNCATE at position 4
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248522   592 slave.cpp:1696] 
> Launching task 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' for framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248641   596 replica.cpp:691] 
> Replica received learned notice for position 4 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.248899   592 paths.cpp:536] Trying 
> to chown 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/slaves/dd11d4ad-2087-4324-99ef-873e83ff09a1-S0/frameworks/dd11d4ad-2087-4324-99ef-873e83ff09a1-0000/executors/b4aadf16-5d8e-4c62-819e-e3c60b46a606/runs/7d74d959-d479-46b6-aad4-0192b4c47bef'
>  to user 'root'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.250741   596 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 2.014661ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.250841   596 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 56857ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.250864   596 replica.cpp:708] 
> Persisted action TRUNCATE at position 4
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.253902   592 slave.cpp:6145] 
> Launching executor 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 with resources cpus(*):0.1; 
> mem(*):32 in work directory 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/slaves/dd11d4ad-2087-4324-99ef-873e83ff09a1-S0/frameworks/dd11d4ad-2087-4324-99ef-873e83ff09a1-0000/executors/b4aadf16-5d8e-4c62-819e-e3c60b46a606/runs/7d74d959-d479-46b6-aad4-0192b4c47bef'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.254106   597 
> containerizer.cpp:978] Starting container 
> 7d74d959-d479-46b6-aad4-0192b4c47bef for executor 
> 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.254119   592 slave.cpp:1982] 
> Queued task 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' for executor 
> 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.254158   592 slave.cpp:868] 
> Successfully attached file 
> '/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/slaves/dd11d4ad-2087-4324-99ef-873e83ff09a1-S0/frameworks/dd11d4ad-2087-4324-99ef-873e83ff09a1-0000/executors/b4aadf16-5d8e-4c62-819e-e3c60b46a606/runs/7d74d959-d479-46b6-aad4-0192b4c47bef'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.255259   598 
> containerizer.cpp:1433] Launching 'mesos-containerizer' with flags 
> '--command="{"arguments":["mesos-executor","--launcher_dir=\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}"
>  --help="false" --pipe_read="16" --pipe_write="23" --pre_exec_commands="[]" 
> --runtime_directory="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_I9WTep/containers/7d74d959-d479-46b6-aad4-0192b4c47bef"
>  --unshare_namespace_mnt="false" --user="root" 
> --working_directory="/mnt/teamcity/temp/buildTmp/PartitionTest_DisconnectedFramework_8dGWjv/slaves/dd11d4ad-2087-4324-99ef-873e83ff09a1-S0/frameworks/dd11d4ad-2087-4324-99ef-873e83ff09a1-0000/executors/b4aadf16-5d8e-4c62-819e-e3c60b46a606/runs/7d74d959-d479-46b6-aad4-0192b4c47bef"'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.255403   596 
> linux_launcher.cpp:421] Launching container 
> 7d74d959-d479-46b6-aad4-0192b4c47bef and cloning with namespaces 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.334707 12465 exec.cpp:162] 
> Version: 1.1.0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.335381   596 slave.cpp:3206] Got 
> registration for executor 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 from executor(1)@172.30.2.234:48038
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.335963 12466 exec.cpp:237] 
> Executor registered on agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.336273   592 slave.cpp:2186] 
> Sending queued task 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' to executor 
> 'b4aadf16-5d8e-4c62-819e-e3c60b46a606' of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 at executor(1)@172.30.2.234:48038
> [03:08:28] :   [Step 10/10] Received SUBSCRIBED event
> [03:08:28] :   [Step 10/10] Subscribed executor on 
> ip-172-30-2-234.mesosphere.io
> [03:08:28] :   [Step 10/10] Received LAUNCH event
> [03:08:28] :   [Step 10/10] Starting task b4aadf16-5d8e-4c62-819e-e3c60b46a606
> [03:08:28] :   [Step 10/10] 
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer launch 
> --command="{"shell":true,"value":"sleep 60"}" --help="false" 
> --unshare_namespace_mnt="false"
> [03:08:28] :   [Step 10/10] Forked command at 12469
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.340229   591 slave.cpp:3609] 
> Handling status update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 from executor(1)@172.30.2.234:48038
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.340754   591 
> status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.340777   591 
> status_update_manager.cpp:500] Creating StatusUpdate stream for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.340987   591 
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 to the agent
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341132   593 slave.cpp:4026] 
> Forwarding the update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 to master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341214   593 slave.cpp:3920] 
> Status update manager successfully handled status update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341256   593 slave.cpp:3936] 
> Sending acknowledgement for status update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 to executor(1)@172.30.2.234:48038
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341279   591 master.cpp:5672] 
> Status update TASK_RUNNING (UUID: 15f79a6a-593f-4dc0-91b3-0de62c8de776) for 
> task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 from agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341313   591 master.cpp:5734] 
> Forwarding status update TASK_RUNNING (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341389   591 master.cpp:7584] 
> Updating the state of task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (latest state: TASK_RUNNING, status 
> update state: TASK_RUNNING)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341533   598 sched.cpp:1025] 
> Scheduler::statusUpdate took 62619ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341698   598 master.cpp:4790] 
> Processing ACKNOWLEDGE call 15f79a6a-593f-4dc0-91b3-0de62c8de776 for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-6267456e-98d6-4a25-8fc8-84f6abc3b7cb@172.30.2.234:37300 on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341828   598 
> status_update_manager.cpp:395] Received status update acknowledgement (UUID: 
> 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.341949   598 slave.cpp:2953] 
> Status update manager successfully handled status update acknowledgement 
> (UUID: 15f79a6a-593f-4dc0-91b3-0de62c8de776) for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.342180   577 master.cpp:1097] 
> Master terminating
> [03:08:28]W:   [Step 10/10] W1004 03:08:28.342229   577 master.cpp:7666] 
> Removing task b4aadf16-5d8e-4c62-819e-e3c60b46a606 with resources cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io) in non-terminal state TASK_RUNNING
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.342386   591 hierarchical.cpp:517] 
> Removed agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.342608   591 hierarchical.cpp:337] 
> Removed framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.342777   593 slave.cpp:4154] Got 
> exited event for master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] W1004 03:08:28.342797   593 slave.cpp:4159] 
> Master disconnected! Waiting for a new master to be elected
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.344710   577 sched.cpp:1995] Asked 
> to stop the driver
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.344791   594 sched.cpp:1187] 
> Stopping framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.345121   577 cluster.cpp:158] 
> Creating default 'local' authorizer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.351191   577 leveldb.cpp:174] 
> Opened db in 5.928194ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.357826   577 leveldb.cpp:181] 
> Compacted db in 6.609499ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.357856   577 leveldb.cpp:196] 
> Created db iterator in 7877ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.357874   577 leveldb.cpp:202] 
> Seeked to beginning of db in 9714ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.357918   577 leveldb.cpp:271] 
> Iterated through 3 keys in the db in 35093ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.357935   577 replica.cpp:776] 
> Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.358204   598 recover.cpp:451] 
> Starting replica recovery
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.358330   595 recover.cpp:477] 
> Replica is in VOTING status
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.358397   595 recover.cpp:466] 
> Recover process terminated
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359127   593 master.cpp:380] 
> Master 7d2df30e-bdeb-42e8-ba63-7b223c820790 (ip-172-30-2-234.mesosphere.io) 
> started on 172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359145   593 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/7rr0oB/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="/usr/local/share/mesos/webui" --work_dir="/tmp/7rr0oB/master" 
> --zk_session_timeout="10secs"
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359366   593 master.cpp:432] 
> Master only allowing authenticated frameworks to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359375   593 master.cpp:446] 
> Master only allowing authenticated agents to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359380   593 master.cpp:459] 
> Master only allowing authenticated HTTP frameworks to register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359386   593 credentials.hpp:37] 
> Loading credentials for authentication from '/tmp/7rr0oB/credentials'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359490   593 master.cpp:504] Using 
> default 'crammd5' authenticator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359539   593 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359591   593 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359638   593 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359696   593 master.cpp:584] 
> Authorization enabled
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359868   592 hierarchical.cpp:149] 
> Initialized hierarchical allocator process
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.359891   596 
> whitelist_watcher.cpp:77] No whitelist given
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.360523   595 master.cpp:2013] 
> Elected as the leading master!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.360539   595 master.cpp:1560] 
> Recovering from registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.360687   594 registrar.cpp:329] 
> Recovering registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.360879   596 log.cpp:553] 
> Attempting to start the writer
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.361315   596 replica.cpp:493] 
> Replica received implicit promise request from 
> __req_res__(3675)@172.30.2.234:37300 with proposal 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.362974   596 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.639131ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.362993   596 replica.cpp:342] 
> Persisted promised to 2
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.363246   592 coordinator.cpp:238] 
> Coordinator attempting to fill missing positions
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.363337   594 log.cpp:569] Writer 
> started with ending position 4
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.363716   595 leveldb.cpp:436] 
> Reading position from leveldb took 29870ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.363759   595 leveldb.cpp:436] 
> Reading position from leveldb took 14641ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.364281   597 registrar.cpp:362] 
> Successfully fetched the registry (356B) in 3.509248ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.364337   597 registrar.cpp:461] 
> Applied 1 operations in 8540ns; attempting to update the registry
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.364531   597 log.cpp:577] 
> Attempting to append 395 bytes to the log
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.364573   597 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.365000   591 replica.cpp:537] 
> Replica received write request for position 5 from 
> __req_res__(3676)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.366381   591 leveldb.cpp:341] 
> Persisting action (414 bytes) to leveldb took 1.359717ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.366400   591 replica.cpp:708] 
> Persisted action APPEND at position 5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.366641   592 replica.cpp:691] 
> Replica received learned notice for position 5 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368288   592 leveldb.cpp:341] 
> Persisting action (416 bytes) to leveldb took 1.628618ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368305   592 replica.cpp:708] 
> Persisted action APPEND at position 5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368649   591 registrar.cpp:506] 
> Successfully updated the registry in 4.289024ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368716   594 log.cpp:596] 
> Attempting to truncate the log to 5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368724   591 registrar.cpp:392] 
> Successfully recovered registrar
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368798   593 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 6
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368902   591 master.cpp:1676] 
> Recovered 1 agents from the registry (356B); allowing 10mins for agents to 
> re-register
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.368989   593 hierarchical.cpp:176] 
> Skipping recovery of hierarchical allocator: nothing to recover
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.369184   593 replica.cpp:537] 
> Replica received write request for position 6 from 
> __req_res__(3677)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.372105   593 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 2.897179ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.372123   593 replica.cpp:708] 
> Persisted action TRUNCATE at position 6
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.372331   598 replica.cpp:691] 
> Replica received learned notice for position 6 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.373744   598 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.388689ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.373778   598 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 17164ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.373787   598 replica.cpp:708] 
> Persisted action TRUNCATE at position 6
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377034   595 slave.cpp:915] New 
> master detected at master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377040   597 
> status_update_manager.cpp:177] Pausing sending status updates
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377049   595 slave.cpp:974] 
> Authenticating with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377063   595 slave.cpp:985] Using 
> default CRAM-MD5 authenticatee
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377104   595 slave.cpp:947] 
> Detecting new master
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377162   592 
> authenticatee.cpp:121] Creating new client SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377439   592 master.cpp:6634] 
> Authenticating slave(261)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377502   598 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(588)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377579   598 authenticator.cpp:98] 
> Creating new server SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377780   598 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377796   598 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377858   594 
> authenticator.cpp:204] Received SASL authentication start
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377903   594 
> authenticator.cpp:326] Authentication requires more steps
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.377951   594 
> authenticatee.cpp:259] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378016   594 
> authenticator.cpp:232] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378039   594 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378051   594 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378065   594 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378079   594 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378089   594 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378098   594 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378113   594 
> authenticator.cpp:318] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378181   598 
> authenticatee.cpp:299] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378188   597 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(588)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378206   594 master.cpp:6664] 
> Successfully authenticated principal 'test-principal' at 
> slave(261)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378371   598 slave.cpp:1069] 
> Successfully authenticated with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378521   598 slave.cpp:1475] Will 
> retry registration in 8.981286ms if necessary
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378629   595 master.cpp:5296] 
> Re-registering agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.378810   598 registrar.cpp:461] 
> Applied 1 operations in 18857ns; attempting to update the registry
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.379026   598 log.cpp:577] 
> Attempting to append 395 bytes to the log
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.379076   598 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 7
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.379384   597 replica.cpp:537] 
> Replica received write request for position 7 from 
> __req_res__(3678)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.381100   597 leveldb.cpp:341] 
> Persisting action (414 bytes) to leveldb took 1.690337ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.381119   597 replica.cpp:708] 
> Persisted action APPEND at position 7
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.381357   597 replica.cpp:691] 
> Replica received learned notice for position 7 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.382861   597 leveldb.cpp:341] 
> Persisting action (416 bytes) to leveldb took 1.481515ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.382879   597 replica.cpp:708] 
> Persisted action APPEND at position 7
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383219   598 registrar.cpp:506] 
> Successfully updated the registry in 4.37504ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383275   594 log.cpp:596] 
> Attempting to truncate the log to 7
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383396   591 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 8
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383430   593 master.cpp:8206] 
> Adding task b4aadf16-5d8e-4c62-819e-e3c60b46a606 with resources cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] W1004 03:08:28.383504   593 master.cpp:7296] 
> Possibly orphaned task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 running on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383580   597 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383599   593 master.cpp:5387] 
> Re-registered agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) with cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383646   593 master.cpp:5481] 
> Sending updated checkpointed resources {} to agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383740   597 slave.cpp:1217] 
> Re-registered with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383779   597 slave.cpp:1253] 
> Forwarding total oversubscribed resources {}
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383823   597 slave.cpp:2738] 
> Ignoring new checkpointed resources identical to the current version: {}
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383839   592 master.cpp:5542] 
> Received update of agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) with total 
> oversubscribed resources {}
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383991   595 
> status_update_manager.cpp:184] Resuming sending status updates
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.383986   594 hierarchical.cpp:485] 
> Added agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 
> (ip-172-30-2-234.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; 
> ports(*):[31000-32000] (allocated: cpus(*):2; mem(*):1024; disk(*):1024; 
> ports(*):[31000-32000])
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384057   594 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384069   598 replica.cpp:537] 
> Replica received write request for position 8 from 
> __req_res__(3679)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384079   594 
> hierarchical.cpp:1309] Performed allocation for agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 in 56812ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384124   594 hierarchical.cpp:555] 
> Agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 (ip-172-30-2-234.mesosphere.io) 
> updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024; 
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; 
> disk(*):1024; ports(*):[31000-32000])
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384173   594 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.384187   594 
> hierarchical.cpp:1309] Performed allocation for agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 in 32682ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.385555   598 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.465195ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.385571   598 replica.cpp:708] 
> Persisted action TRUNCATE at position 8
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.385834   596 replica.cpp:691] 
> Replica received learned notice for position 8 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.387387   596 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.528808ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.387426   596 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 19292ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.387437   596 replica.cpp:708] 
> Persisted action TRUNCATE at position 8
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.387974   592 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388000   592 
> hierarchical.cpp:1286] Performed allocation for 1 agents in 65051ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388026   593 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388088   593 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388135   593 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388347   592 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388356   597 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388363   592 
> hierarchical.cpp:1286] Performed allocation for 1 agents in 37142ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388406   597 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388475   592 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388640   593 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388653   596 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388664   593 
> hierarchical.cpp:1286] Performed allocation for 1 agents in 45878ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388732   596 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.388788   596 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389056   595 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389062   596 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389078   595 
> hierarchical.cpp:1286] Performed allocation for 1 agents in 49195ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389101   596 slave.cpp:5019] 
> Current disk usage 1.79%. Max allowed age: 6.174624373243669days
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389178   596 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.389217   596 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390621   598 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390625   596 slave.cpp:5428] 
> Querying resource estimator for oversubscribable resources
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390656   594 master.cpp:5883] 
> Marking agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at 
> slave(261)@172.30.2.234:37300 (ip-172-30-2-234.mesosphere.io) unreachable: 
> health check timed out
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390651   598 
> hierarchical.cpp:1286] Performed allocation for 1 agents in 63038ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390720   596 slave.cpp:4108] 
> Received ping from slave-observer(263)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390826   596 slave.cpp:5442] 
> Received oversubscribable resources {} from the resource estimator
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.390880   592 registrar.cpp:461] 
> Applied 1 operations in 29815ns; attempting to update the registry
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.391151   594 log.cpp:577] 
> Attempting to append 270 bytes to the log
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.391230   593 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 9
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.391655   598 replica.cpp:537] 
> Replica received write request for position 9 from 
> __req_res__(3680)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.393128   598 leveldb.cpp:341] 
> Persisting action (289 bytes) to leveldb took 1.448084ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.393146   598 replica.cpp:708] 
> Persisted action APPEND at position 9
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.393594   595 replica.cpp:691] 
> Replica received learned notice for position 9 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395082   595 leveldb.cpp:341] 
> Persisting action (291 bytes) to leveldb took 1.466355ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395102   595 replica.cpp:708] 
> Persisted action APPEND at position 9
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395380   594 registrar.cpp:506] 
> Successfully updated the registry in 0ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395397   591 log.cpp:596] 
> Attempting to truncate the log to 9
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395445   593 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 10
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395476   594 master.cpp:5930] 
> Marked agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 
> (ip-172-30-2-234.mesosphere.io) unreachable: health check timed out
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395532   594 master.cpp:7584] 
> Updating the state of task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (latest state: TASK_LOST, status 
> update state: TASK_LOST)
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395648   597 hierarchical.cpp:517] 
> Removed agent dd11d4ad-2087-4324-99ef-873e83ff09a1-S0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395670   594 master.cpp:7680] 
> Removing task b4aadf16-5d8e-4c62-819e-e3c60b46a606 with resources cpus(*):2; 
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 on agent 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-S0 at slave(261)@172.30.2.234:37300 
> (ip-172-30-2-234.mesosphere.io)
> [03:08:28]W:   [Step 10/10] W1004 03:08:28.395733   594 master.cpp:5993] 
> Dropping update TASK_LOST for task b4aadf16-5d8e-4c62-819e-e3c60b46a606 of 
> framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 for unknown framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.395740   595 replica.cpp:537] 
> Replica received write request for position 10 from 
> __req_res__(3681)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.397158   595 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.396704ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.397176   595 replica.cpp:708] 
> Persisted action TRUNCATE at position 10
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.397415   598 replica.cpp:691] 
> Replica received learned notice for position 10 from @0.0.0.0:0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.398802   598 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.362316ms
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.398839   598 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 18152ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.398849   598 replica.cpp:708] 
> Persisted action TRUNCATE at position 10
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.399632   577 sched.cpp:226] 
> Version: 1.1.0
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.399807   595 sched.cpp:330] New 
> master detected at master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.399840   595 sched.cpp:396] 
> Authenticating with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.399848   595 sched.cpp:403] Using 
> default CRAM-MD5 authenticatee
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.399940   596 
> authenticatee.cpp:121] Creating new client SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400151   596 master.cpp:6634] 
> Authenticating 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400226   593 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(589)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400318   598 authenticator.cpp:98] 
> Creating new server SASL connection
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400524   598 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400540   598 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400637   596 
> authenticator.cpp:204] Received SASL authentication start
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400686   596 
> authenticator.cpp:326] Authentication requires more steps
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400748   596 
> authenticatee.cpp:259] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400826   596 
> authenticator.cpp:232] Received SASL authentication step
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400849   596 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400861   596 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400879   596 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400895   596 auxprop.cpp:109] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-234.mesosphere.io' server FQDN: 'ip-172-30-2-234.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400907   596 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400915   596 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400931   596 
> authenticator.cpp:318] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.400988   598 
> authenticatee.cpp:299] Authentication success
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401007   596 master.cpp:6664] 
> Successfully authenticated principal 'test-principal' at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401036   595 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(589)@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401144   598 sched.cpp:502] 
> Successfully authenticated with master master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401157   598 sched.cpp:820] 
> Sending SUBSCRIBE call to master@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401204   598 sched.cpp:853] Will 
> retry registration in 1.880383118secs if necessary
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401257   598 master.cpp:2587] 
> Received SUBSCRIBE call for framework 'default' at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401296   598 master.cpp:2049] 
> Authorizing framework principal 'test-principal' to receive offers for role 
> '*'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401454   593 master.cpp:2663] 
> Subscribing framework default with checkpointing disabled and capabilities [  
> ]
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401613   598 hierarchical.cpp:275] 
> Added framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401633   598 
> hierarchical.cpp:1694] No allocations performed
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401638   598 
> hierarchical.cpp:1789] No inverse offers to send out!
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401636   593 sched.cpp:743] 
> Framework registered with dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401648   598 
> hierarchical.cpp:1286] Performed allocation for 0 agents in 22167ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401670   593 sched.cpp:757] 
> Scheduler::registered took 14515ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401873   596 master.cpp:6173] 
> Performing explicit task state reconciliation for 1 tasks of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.401914   596 master.cpp:6291] 
> Sending explicit reconciliation state TASK_LOST for task 
> b4aadf16-5d8e-4c62-819e-e3c60b46a606 of framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402048   596 sched.cpp:1025] 
> Scheduler::statusUpdate took 21602ns
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402101   577 sched.cpp:1995] Asked 
> to stop the driver
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402171   592 sched.cpp:1187] 
> Stopping framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402261   598 master.cpp:7037] 
> Processing TEARDOWN call for framework 
> dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402287   598 master.cpp:7049] 
> Removing framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000 (default) at 
> scheduler-db310e38-f87f-4b2e-acdc-2ce07bcedac6@172.30.2.234:37300
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.402922   592 process.cpp:3377] 
> Handling HTTP event for process 'metrics' with path: '/metrics/snapshot'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.403093   596 http.cpp:699] 
> Authorizing principal 'ANY' to GET the endpoint '/metrics/snapshot'
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.403786   595 hierarchical.cpp:386] 
> Deactivated framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.403841   595 hierarchical.cpp:337] 
> Removed framework dd11d4ad-2087-4324-99ef-873e83ff09a1-0000
> [03:08:28]W:   [Step 10/10] F1004 03:08:28.403998   595 sorter.cpp:450] Check 
> failed: contains(name) 
> [03:08:28]W:   [Step 10/10] *** Check failure stack trace: ***
> [03:08:28]W:   [Step 10/10]     @     0x7fe1335d688d  
> google::LogMessage::Fail()
> [03:08:28]W:   [Step 10/10]     @     0x7fe1335d85cc  
> google::LogMessage::SendToLog()
> [03:08:28]W:   [Step 10/10]     @     0x7fe1335d647c  
> google::LogMessage::Flush()
> [03:08:28]W:   [Step 10/10]     @     0x7fe1335d8ec9  
> google::LogMessageFatal::~LogMessageFatal()
> [03:08:28]W:   [Step 10/10]     @     0x7fe132cc47d0  
> mesos::internal::master::allocator::DRFSorter::calculateShare()
> [03:08:28]W:   [Step 10/10]     @     0x7fe132cc41a9  
> _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8internal8DispatchIdEclIRKZN5mesos8internal6master9allocator7Metrics3addERKSsEUlvE_EENS0_6FutureIdEERKNS0_4UPIDEOT_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
> [03:08:28]W:   [Step 10/10]     @     0x7fe13355dd81  
> process::ProcessManager::resume()
> [03:08:28]W:   [Step 10/10]     @     0x7fe13355e087  
> _ZNSt6thread5_ImplISt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEEE6_M_runEv
> [03:08:28]W:   [Step 10/10]     @     0x7fe1315b8220  (unknown)
> [03:08:28]W:   [Step 10/10]     @     0x7fe131c1edc5  start_thread
> [03:08:28]W:   [Step 10/10]     @     0x7fe130d1fced  __clone
> [03:08:28]W:   [Step 10/10] I1004 03:08:28.423413 12461 exec.cpp:496] Agent 
> exited ... shutting down
> [03:08:28]W:   [Step 10/10] 
> /mnt/teamcity/temp/agentTmp/custom_script3774393573526818187: line 3:   577 
> Aborted                 GLOG_v=1 ./bin/mesos-tests.sh --verbose 
> --gtest_filter="$GTEST_FILTER"
> {noformat}



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

Reply via email to