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