[ 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)