You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2016/10/11 21:53:20 UTC
[jira] [Comment Edited] (MESOS-6308) CHECK failure in DRF sorter.
[ https://issues.apache.org/jira/browse/MESOS-6308?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15566725#comment-15566725 ]
Benjamin Mahler edited comment on MESOS-6308 at 10/11/16 9:52 PM:
------------------------------------------------------------------
Thanks for the analysis [~gyliu]. Mind adding a note that we don't check for client presence because of the asynchronous metrics issue you found? Could we return an option and CHECK accordingly in the callers (the metric code will not CHECK due to this race)? Returning 0 sounds ok, but I'm a bit hesitant to do this over returning an option, as may miss consistency issues in the future.
was (Author: bmahler):
Thanks for the analysis [~gyliu]. Mind adding a note that we don't check for client presence because of the asynchronous metrics issue you found? Could we return an option and CHECK accordingly in the callers (the metric code will not CHECK due to this race)? Returning 0 sounds ok, but I'm a bit hesitant that we'll miss consistency issues in the future.
> 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)