[
https://issues.apache.org/jira/browse/MESOS-8049?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Alexander Rukletsov updated MESOS-8049:
---------------------------------------
Labels: flaky flaky-test (was: crashed flaky flaky-test)
> MasterTest.RecoveredFramework is flaky and crashes.
> ---------------------------------------------------
>
> Key: MESOS-8049
> URL: https://issues.apache.org/jira/browse/MESOS-8049
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 1.5.0
> Environment: ubuntu-17.04
> Reporter: Till Toenshoff
> Labels: flaky, flaky-test
>
> Observed on internal CI:
> {noformat}
> 00:35:26 [ RUN ] MasterTest.RecoveredFramework
> 00:35:26 I0930 00:35:26.319862 27033 cluster.cpp:162] Creating default
> 'local' authorizer
> 00:35:26 I0930 00:35:26.321624 27053 master.cpp:445] Master
> 94ab36ee-4c02-457d-ae35-2f130ae826f5 (ip-172-16-10-150) started on
> 172.16.10.150:37345
> 00:35:26 I0930 00:35:26.321647 27053 master.cpp:447] 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/Z8B1GQ/credentials"
> --filter_gpu_resources="true" --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"
> --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="in_memory"
> --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/Z8B1GQ/master"
> --zk_session_timeout="10secs"
> 00:35:26 I0930 00:35:26.321758 27053 master.cpp:497] Master only allowing
> authenticated frameworks to register
> 00:35:26 I0930 00:35:26.321768 27053 master.cpp:511] Master only allowing
> authenticated agents to register
> 00:35:26 I0930 00:35:26.321772 27053 master.cpp:524] Master only allowing
> authenticated HTTP frameworks to register
> 00:35:26 I0930 00:35:26.321777 27053 credentials.hpp:37] Loading credentials
> for authentication from '/tmp/Z8B1GQ/credentials'
> 00:35:26 I0930 00:35:26.321853 27053 master.cpp:569] Using default 'crammd5'
> authenticator
> 00:35:26 I0930 00:35:26.321892 27053 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-readonly'
> 00:35:26 I0930 00:35:26.321923 27053 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-readwrite'
> 00:35:26 I0930 00:35:26.321946 27053 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-scheduler'
> 00:35:26 I0930 00:35:26.321969 27053 master.cpp:649] Authorization enabled
> 00:35:26 I0930 00:35:26.322120 27048 hierarchical.cpp:171] Initialized
> hierarchical allocator process
> 00:35:26 I0930 00:35:26.322145 27048 whitelist_watcher.cpp:77] No whitelist
> given
> 00:35:26 I0930 00:35:26.322657 27053 master.cpp:2216] Elected as the leading
> master!
> 00:35:26 I0930 00:35:26.322679 27053 master.cpp:1705] Recovering from
> registrar
> 00:35:26 I0930 00:35:26.322721 27053 registrar.cpp:347] Recovering registrar
> 00:35:26 I0930 00:35:26.322829 27048 registrar.cpp:391] Successfully fetched
> the registry (0B) in 90368ns
> 00:35:26 I0930 00:35:26.322856 27048 registrar.cpp:495] Applied 1 operations
> in 4113ns; attempting to update the registry
> 00:35:26 I0930 00:35:26.322960 27053 registrar.cpp:552] Successfully updated
> the registry in 89088ns
> 00:35:26 I0930 00:35:26.323011 27053 registrar.cpp:424] Successfully
> recovered registrar
> 00:35:26 I0930 00:35:26.323148 27054 master.cpp:1809] Recovered 0 agents from
> the registry (146B); allowing 10mins for agents to re-register
> 00:35:26 I0930 00:35:26.323161 27047 hierarchical.cpp:209] Skipping recovery
> of hierarchical allocator: nothing to recover
> 00:35:26 W0930 00:35:26.325556 27033 process.cpp:3194] Attempted to spawn
> already running process [email protected]:37345
> 00:35:26 I0930 00:35:26.325654 27033 cluster.cpp:448] Creating default
> 'local' authorizer
> 00:35:26 I0930 00:35:26.326050 27048 slave.cpp:254] Mesos agent started on
> (250)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.326066 27048 slave.cpp:255] Flags at startup:
> --acls="" --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/MasterTest_RecoveredFramework_6nFcY6/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_RecoveredFramework_6nFcY6/credential"
> --default_role="*" --disallow_sharing_agent_pid_namespace="false"
> --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/MasterTest_RecoveredFramework_6nFcY6/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_reregistration_timeout="2secs"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterTest_RecoveredFramework_6nFcY6/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_command_executor="false"
> --http_credentials="/tmp/MasterTest_RecoveredFramework_6nFcY6/http_credentials"
> --http_heartbeat_interval="30secs" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem" --launcher="linux"
> --launcher_dir="/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/Plain/label/mesos-ec2-ubuntu-17.04/mesos/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --max_completed_executors_per_framework="150"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
> --quiet="false" --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ns"
> --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true"
> --runtime_dir="/tmp/MasterTest_RecoveredFramework_6nFcY6"
> --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_RecoveredFramework_Cf2BPY"
> --zk_session_timeout="10secs"
> 00:35:26 I0930 00:35:26.326205 27048 credentials.hpp:86] Loading credential
> for authentication from '/tmp/MasterTest_RecoveredFramework_6nFcY6/credential'
> 00:35:26 I0930 00:35:26.326249 27048 slave.cpp:287] Agent using credential
> for: test-principal
> 00:35:26 I0930 00:35:26.326259 27048 credentials.hpp:37] Loading credentials
> for authentication from
> '/tmp/MasterTest_RecoveredFramework_6nFcY6/http_credentials'
> 00:35:26 I0930 00:35:26.326350 27048 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-agent-readonly'
> 00:35:26 I0930 00:35:26.326421 27048 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-agent-readwrite'
> 00:35:26 W0930 00:35:26.326930 27033 process.cpp:3194] Attempted to spawn
> already running process [email protected]:37345
> 00:35:26 I0930 00:35:26.327750 27048 slave.cpp:585] Agent resources:
> [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> 00:35:26 I0930 00:35:26.327836 27048 slave.cpp:593] Agent attributes: [ ]
> 00:35:26 I0930 00:35:26.327844 27048 slave.cpp:602] Agent hostname:
> ip-172-16-10-150
> 00:35:26 I0930 00:35:26.328181 27050 status_update_manager.cpp:177] Pausing
> sending status updates
> 00:35:26 I0930 00:35:26.328267 27048 state.cpp:64] Recovering state from
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/meta'
> 00:35:26 I0930 00:35:26.328359 27048 status_update_manager.cpp:203]
> Recovering status update manager
> 00:35:26 I0930 00:35:26.328440 27048 slave.cpp:6313] Finished recovery
> 00:35:26 I0930 00:35:26.328673 27048 slave.cpp:6495] Querying resource
> estimator for oversubscribable resources
> 00:35:26 I0930 00:35:26.328924 27048 status_update_manager.cpp:177] Pausing
> sending status updates
> 00:35:26 I0930 00:35:26.329135 27050 slave.cpp:993] New master detected at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.329509 27050 slave.cpp:1028] Detecting new master
> 00:35:26 I0930 00:35:26.329551 27050 slave.cpp:6509] Received
> oversubscribable resources {} from the resource estimator
> 00:35:26 I0930 00:35:26.329768 27033 sched.cpp:232] Version: 1.5.0
> 00:35:26 I0930 00:35:26.329958 27052 sched.cpp:336] New master detected at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.329989 27052 sched.cpp:407] Authenticating with
> master [email protected]:37345
> 00:35:26 I0930 00:35:26.329996 27052 sched.cpp:414] Using default CRAM-MD5
> authenticatee
> 00:35:26 I0930 00:35:26.330178 27047 authenticatee.cpp:121] Creating new
> client SASL connection
> 00:35:26 I0930 00:35:26.330443 27048 slave.cpp:1055] Authenticating with
> master [email protected]:37345
> 00:35:26 I0930 00:35:26.330468 27048 slave.cpp:1066] Using default CRAM-MD5
> authenticatee
> 00:35:26 I0930 00:35:26.330519 27048 authenticatee.cpp:121] Creating new
> client SASL connection
> 00:35:26 I0930 00:35:26.331699 27047 master.cpp:7915] Authenticating
> [email protected]:37345
> 00:35:26 I0930 00:35:26.331897 27047 authenticator.cpp:414] Starting
> authentication session for crammd5-authenticatee(525)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.332067 27047 authenticator.cpp:98] Creating new
> server SASL connection
> 00:35:26 I0930 00:35:26.332506 27048 master.cpp:7915] Authenticating
> slave(250)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.332562 27049 authenticator.cpp:414] Starting
> authentication session for crammd5-authenticatee(526)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.332623 27049 authenticator.cpp:98] Creating new
> server SASL connection
> 00:35:26 I0930 00:35:26.333696 27047 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> 00:35:26 I0930 00:35:26.334159 27047 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> 00:35:26 I0930 00:35:26.334375 27048 authenticator.cpp:204] Received SASL
> authentication start
> 00:35:26 I0930 00:35:26.334410 27048 authenticator.cpp:326] Authentication
> requires more steps
> 00:35:26 I0930 00:35:26.334636 27047 authenticatee.cpp:259] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.334605 27049 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> 00:35:26 I0930 00:35:26.334756 27049 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> 00:35:26 I0930 00:35:26.334792 27049 authenticator.cpp:204] Received SASL
> authentication start
> 00:35:26 I0930 00:35:26.334820 27049 authenticator.cpp:326] Authentication
> requires more steps
> 00:35:26 I0930 00:35:26.334849 27049 authenticatee.cpp:259] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.334879 27049 authenticator.cpp:232] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.334893 27049 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> 00:35:26 I0930 00:35:26.334902 27049 auxprop.cpp:181] Looking up auxiliary
> property '*userPassword'
> 00:35:26 I0930 00:35:26.334910 27049 auxprop.cpp:181] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> 00:35:26 I0930 00:35:26.334918 27049 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> 00:35:26 I0930 00:35:26.334923 27049 auxprop.cpp:131] Skipping auxiliary
> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.334928 27049 auxprop.cpp:131] Skipping auxiliary
> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.334939 27049 authenticator.cpp:318] Authentication
> success
> 00:35:26 I0930 00:35:26.334972 27049 authenticatee.cpp:299] Authentication
> success
> 00:35:26 I0930 00:35:26.334996 27049 master.cpp:7945] Successfully
> authenticated principal 'test-principal' at slave(250)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.335019 27049 authenticator.cpp:432] Authentication
> session cleanup for crammd5-authenticatee(526)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.335070 27049 slave.cpp:1150] Successfully
> authenticated with master [email protected]:37345
> 00:35:26 I0930 00:35:26.335117 27049 slave.cpp:1629] Will retry registration
> in 16ns if necessary
> 00:35:26 I0930 00:35:26.335191 27049 master.cpp:5819] Received register agent
> message from slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.335222 27049 master.cpp:3856] Authorizing agent with
> principal 'test-principal'
> 00:35:26 I0930 00:35:26.335300 27049 master.cpp:5879] Authorized registration
> of agent at slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.335335 27049 master.cpp:5972] Registering agent at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150) with id
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0
> 00:35:26 I0930 00:35:26.335423 27049 registrar.cpp:495] Applied 1 operations
> in 10760ns; attempting to update the registry
> 00:35:26 I0930 00:35:26.334756 27050 authenticator.cpp:232] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.335621 27049 slave.cpp:1629] Will retry registration
> in 1ns if necessary
> 00:35:26 I0930 00:35:26.335652 27053 master.cpp:5813] Ignoring register agent
> message from slave(250)@172.16.10.150:37345 (ip-172-16-10-150) as
> registration is already in progress
> 00:35:26 I0930 00:35:26.335675 27050 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> 00:35:26 I0930 00:35:26.335685 27050 auxprop.cpp:181] Looking up auxiliary
> property '*userPassword'
> 00:35:26 I0930 00:35:26.335693 27050 auxprop.cpp:181] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> 00:35:26 I0930 00:35:26.335701 27050 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> 00:35:26 I0930 00:35:26.335706 27050 auxprop.cpp:131] Skipping auxiliary
> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.335711 27050 auxprop.cpp:131] Skipping auxiliary
> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.335721 27050 authenticator.cpp:318] Authentication
> success
> 00:35:26 I0930 00:35:26.335757 27053 authenticatee.cpp:299] Authentication
> success
> 00:35:26 I0930 00:35:26.335781 27053 master.cpp:7945] Successfully
> authenticated principal 'test-principal' at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.335804 27053 authenticator.cpp:432] Authentication
> session cleanup for crammd5-authenticatee(525)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.335850 27048 sched.cpp:513] Successfully
> authenticated with master [email protected]:37345
> 00:35:26 I0930 00:35:26.335862 27048 sched.cpp:836] Sending SUBSCRIBE call to
> [email protected]:37345
> 00:35:26 I0930 00:35:26.335892 27048 sched.cpp:869] Will retry registration
> in 1.365409978secs if necessary
> 00:35:26 I0930 00:35:26.335954 27048 master.cpp:2947] Received SUBSCRIBE call
> for framework 'default' at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.335978 27048 master.cpp:2281] Authorizing framework
> principal 'test-principal' to receive offers for roles '{ * }'
> 00:35:26 I0930 00:35:26.336056 27048 master.cpp:3027] Subscribing framework
> default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT
> ]
> 00:35:26 I0930 00:35:26.336153 27047 registrar.cpp:552] Successfully updated
> the registry in 710144ns
> 00:35:26 I0930 00:35:26.336194 27048 hierarchical.cpp:303] Added framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.336267 27049 sched.cpp:759] Framework registered with
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.336350 27049 sched.cpp:773] Scheduler::registered
> took 12378ns
> 00:35:26 I0930 00:35:26.336392 27048 hierarchical.cpp:1943] No allocations
> performed
> 00:35:26 I0930 00:35:26.336410 27048 hierarchical.cpp:2033] No inverse offers
> to send out!
> 00:35:26 I0930 00:35:26.336417 27048 hierarchical.cpp:1486] Performed
> allocation for 0 agents in 29467ns
> 00:35:26 I0930 00:35:26.336549 27053 master.cpp:6019] Admitted agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.336741 27050 hierarchical.cpp:593] Added agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 (ip-172-16-10-150) with cpus:2;
> mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
> 00:35:26 I0930 00:35:26.336676 27053 master.cpp:6050] Registered agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150) with
> [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> 00:35:26 I0930 00:35:26.336799 27053 slave.cpp:4969] Received ping from
> slave-observer(245)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.336835 27053 slave.cpp:1196] Registered with master
> [email protected]:37345; given agent ID
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0
> 00:35:26 I0930 00:35:26.336959 27050 hierarchical.cpp:2033] No inverse offers
> to send out!
> 00:35:26 I0930 00:35:26.336975 27050 hierarchical.cpp:1486] Performed
> allocation for 1 agents in 186165ns
> 00:35:26 I0930 00:35:26.336980 27053 slave.cpp:1216] Checkpointing SlaveInfo
> to
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/meta/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/slave.info'
> 00:35:26 I0930 00:35:26.337002 27050 status_update_manager.cpp:184] Resuming
> sending status updates
> 00:35:26 I0930 00:35:26.337121 27050 master.cpp:7745] Sending 1 offers to
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 (default) at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.337136 27053 slave.cpp:1265] Forwarding total
> oversubscribed resources {}
> 00:35:26 I0930 00:35:26.337188 27050 master.cpp:6814] Received update of
> agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150) with total oversubscribed
> resources {}
> 00:35:26 I0930 00:35:26.337257 27050 hierarchical.cpp:660] Agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 (ip-172-16-10-150) updated with total
> resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> 00:35:26 I0930 00:35:26.337404 27053 sched.cpp:933] Scheduler::resourceOffers
> took 158280ns
> 00:35:26 I0930 00:35:26.337635 27053 master.cpp:9368] Removing offer
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-O0
> 00:35:26 I0930 00:35:26.337685 27053 master.cpp:4214] Processing ACCEPT call
> for offers: [ 94ab36ee-4c02-457d-ae35-2f130ae826f5-O0 ] on agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150) for framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> (default) at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.337718 27053 master.cpp:3583] Authorizing framework
> principal 'test-principal' to launch task 0
> 00:35:26 W0930 00:35:26.338078 27053 validation.cpp:1338] Executor 'default'
> for task '0' uses less CPUs (None) than the minimum required (0.01). Please
> update your executor, as this will be mandatory in future releases.
> 00:35:26 W0930 00:35:26.338104 27053 validation.cpp:1350] Executor 'default'
> for task '0' uses less memory (None) than the minimum required (32MB). Please
> update your executor, as this will be mandatory in future releases.
> 00:35:26 I0930 00:35:26.338172 27053 master.cpp:10114] Adding task 0 with
> resources
> [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":64.0},"type":"SCALAR"}]
> on agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.338266 27053 master.cpp:4897] Launching task 0 of
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 (default) at
> [email protected]:37345 with
> resources
> [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":64.0},"type":"SCALAR"}]
> on agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.338474 27053 slave.cpp:1750] Got assigned task '0'
> for framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.338649 27053 slave.cpp:2018] Authorizing task '0' for
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.338680 27053 slave.cpp:6812] Authorizing framework
> principal 'test-principal' to launch task 0
> 00:35:26 I0930 00:35:26.338909 27053 hierarchical.cpp:887] Updated allocation
> of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 on agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 from cpus(allocated: *):2;
> mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
> *):[31000-32000] to cpus(allocated: *):2; mem(allocated: *):1024;
> disk(allocated: *):1024; ports(allocated: *):[31000-32000]
> 00:35:26 I0930 00:35:26.339054 27053 hierarchical.cpp:1161] Recovered
> cpus(allocated: *):1; mem(allocated: *):960; disk(allocated: *):1024;
> ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024;
> ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):64)
> on agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 from framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.339083 27053 hierarchical.cpp:1207] Framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 filtered agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 for 5secs
> 00:35:26 I0930 00:35:26.339254 27047 slave.cpp:2186] Launching task '0' for
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.339488 27047 paths.cpp:594] Trying to chown
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> to user 'root'
> 00:35:26 I0930 00:35:26.339608 27047 slave.cpp:7274] Launching executor
> 'default' of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 with
> resources [] in work directory
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> 00:35:26 I0930 00:35:26.339809 27047 slave.cpp:2877] Launching container
> 0c8dec65-80ef-42ae-9ff5-1242c64f4379 for executor 'default' of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 W0930 00:35:26.340411 27050 process.cpp:3194] Attempted to spawn
> already running process [email protected]:37345
> 00:35:26 I0930 00:35:26.340467 27050 exec.cpp:162] Version: 1.5.0
> 00:35:26 I0930 00:35:26.340576 27050 exec.cpp:212] Executor started at:
> executor(83)@172.16.10.150:37345 with pid 27033
> 00:35:26 I0930 00:35:26.340684 27047 slave.cpp:2414] Queued task '0' for
> executor 'default' of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.340720 27047 slave.cpp:944] Successfully attached
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> to virtual path
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/latest'
> 00:35:26 I0930 00:35:26.340739 27047 slave.cpp:944] Successfully attached
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> to virtual path
> '/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/latest'
> 00:35:26 I0930 00:35:26.340751 27047 slave.cpp:944] Successfully attached
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> to virtual path
> '/tmp/MasterTest_RecoveredFramework_Cf2BPY/slaves/94ab36ee-4c02-457d-ae35-2f130ae826f5-S0/frameworks/94ab36ee-4c02-457d-ae35-2f130ae826f5-0000/executors/default/runs/0c8dec65-80ef-42ae-9ff5-1242c64f4379'
> 00:35:26 I0930 00:35:26.340790 27047 slave.cpp:3944] Got registration for
> executor 'default' of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> from executor(83)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.340952 27048 exec.cpp:237] Executor registered on
> agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0
> 00:35:26 I0930 00:35:26.340977 27048 exec.cpp:249] Executor::registered took
> 8523ns
> 00:35:26 I0930 00:35:26.341020 27048 slave.cpp:2616] Sending queued task '0'
> to executor 'default' of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> at executor(83)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.341096 27048 exec.cpp:331] Executor asked to run task
> '0'
> 00:35:26 I0930 00:35:26.341116 27048 exec.cpp:340] Executor::launchTask took
> 10359ns
> 00:35:26 I0930 00:35:26.341135 27048 exec.cpp:571] Executor sending status
> update TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0
> of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341202 27048 slave.cpp:4398] Handling status update
> TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0 of
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 from
> executor(83)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.341377 27049 status_update_manager.cpp:323] Received
> status update TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for
> task 0 of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341398 27049 status_update_manager.cpp:500] Creating
> StatusUpdate stream for task 0 of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341500 27049 status_update_manager.cpp:377]
> Forwarding update TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec)
> for task 0 of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 to the agent
> 00:35:26 I0930 00:35:26.341575 27049 slave.cpp:4879] Forwarding the update
> TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0 of
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 to
> [email protected]:37345
> 00:35:26 I0930 00:35:26.341644 27049 slave.cpp:4773] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0 of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341662 27049 slave.cpp:4789] Sending acknowledgement
> for status update TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec)
> for task 0 of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 to
> executor(83)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.341694 27053 master.cpp:6972] Status update
> TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0 of
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 from agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.341718 27053 master.cpp:7034] Forwarding status
> update TASK_RUNNING (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0
> of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341702 27049 exec.cpp:388] Executor received status
> update acknowledgement 008f07c2-fbd8-4a8c-a7b5-df52f470ecec for task 0 of
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.341780 27053 master.cpp:9136] Updating the state of
> task 0 of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 (latest state:
> TASK_RUNNING, status update state: TASK_RUNNING)
> 00:35:26 I0930 00:35:26.341855 27049 sched.cpp:1041] Scheduler::statusUpdate
> took 29241ns
> 00:35:26 I0930 00:35:26.341938 27049 master.cpp:5584] Processing ACKNOWLEDGE
> call 008f07c2-fbd8-4a8c-a7b5-df52f470ecec for task 0 of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 (default) at
> [email protected]:37345 on agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0
> 00:35:26 I0930 00:35:26.342033 27049 status_update_manager.cpp:395] Received
> status update acknowledgement (UUID: 008f07c2-fbd8-4a8c-a7b5-df52f470ecec)
> for task 0 of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.342100 27049 slave.cpp:3682] Status update manager
> successfully handled status update acknowledgement (UUID:
> 008f07c2-fbd8-4a8c-a7b5-df52f470ecec) for task 0 of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.342774 27048 process.cpp:3929] Handling HTTP event
> for process 'master' with path: '/master/state'
> 00:35:26 I0930 00:35:26.343066 27047 http.cpp:1185] HTTP GET for
> /master/state from 172.16.10.150:34280
> 00:35:26 I0930 00:35:26.344730 27033 master.cpp:1163] Master terminating
> 00:35:26 I0930 00:35:26.344885 27048 hierarchical.cpp:626] Removed agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0
> 00:35:26 W0930 00:35:26.344918 27033 master.cpp:9216] Removing task 0 with
> resources
> [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":64.0},"type":"SCALAR"}]
> of framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 on agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150) in non-removable state TASK_RUNNING
> 00:35:26 I0930 00:35:26.345073 27033 master.cpp:9259] Removing executor
> 'default' with resources [] of framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 on agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.350461 27054 hierarchical.cpp:355] Removed framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.350694 27051 slave.cpp:5011] Got exited event for
> [email protected]:37345
> 00:35:26 W0930 00:35:26.350720 27051 slave.cpp:5016] Master disconnected!
> Waiting for a new master to be elected
> 00:35:26 I0930 00:35:26.351819 27033 cluster.cpp:162] Creating default
> 'local' authorizer
> 00:35:26 I0930 00:35:26.354027 27054 master.cpp:445] Master
> 1ceb0a42-b161-461a-872f-a19f735769bf (ip-172-16-10-150) started on
> 172.16.10.150:37345
> 00:35:26 I0930 00:35:26.354048 27054 master.cpp:447] 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/Z8B1GQ/credentials"
> --filter_gpu_resources="true" --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"
> --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="in_memory"
> --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/Z8B1GQ/master"
> --zk_session_timeout="10secs"
> 00:35:26 I0930 00:35:26.354140 27054 master.cpp:497] Master only allowing
> authenticated frameworks to register
> 00:35:26 I0930 00:35:26.354145 27054 master.cpp:511] Master only allowing
> authenticated agents to register
> 00:35:26 I0930 00:35:26.354147 27054 master.cpp:524] Master only allowing
> authenticated HTTP frameworks to register
> 00:35:26 I0930 00:35:26.354151 27054 credentials.hpp:37] Loading credentials
> for authentication from '/tmp/Z8B1GQ/credentials'
> 00:35:26 I0930 00:35:26.354212 27054 master.cpp:569] Using default 'crammd5'
> authenticator
> 00:35:26 I0930 00:35:26.354243 27054 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-readonly'
> 00:35:26 I0930 00:35:26.354356 27054 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-readwrite'
> 00:35:26 I0930 00:35:26.354492 27054 http.cpp:1045] Creating default 'basic'
> HTTP authenticator for realm 'mesos-master-scheduler'
> 00:35:26 I0930 00:35:26.354544 27054 master.cpp:649] Authorization enabled
> 00:35:26 I0930 00:35:26.354645 27047 hierarchical.cpp:171] Initialized
> hierarchical allocator process
> 00:35:26 I0930 00:35:26.354665 27048 whitelist_watcher.cpp:77] No whitelist
> given
> 00:35:26 I0930 00:35:26.355301 27049 master.cpp:2216] Elected as the leading
> master!
> 00:35:26 I0930 00:35:26.355319 27049 master.cpp:1705] Recovering from
> registrar
> 00:35:26 I0930 00:35:26.355351 27049 registrar.cpp:347] Recovering registrar
> 00:35:26 I0930 00:35:26.355532 27053 registrar.cpp:391] Successfully fetched
> the registry (0B) in 0ns
> 00:35:26 I0930 00:35:26.355561 27053 registrar.cpp:495] Applied 1 operations
> in 3905ns; attempting to update the registry
> 00:35:26 I0930 00:35:26.358402 27049 registrar.cpp:552] Successfully updated
> the registry in 0ns
> 00:35:26 I0930 00:35:26.358444 27049 registrar.cpp:424] Successfully
> recovered registrar
> 00:35:26 I0930 00:35:26.358543 27049 master.cpp:1809] Recovered 0 agents from
> the registry (146B); allowing 10mins for agents to re-register
> 00:35:26 I0930 00:35:26.358597 27049 hierarchical.cpp:209] Skipping recovery
> of hierarchical allocator: nothing to recover
> 00:35:26 I0930 00:35:26.359922 27051 sched.cpp:330] Scheduler::disconnected
> took 7921ns
> 00:35:26 I0930 00:35:26.359941 27051 sched.cpp:336] New master detected at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.360000 27048 slave.cpp:993] New master detected at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.360007 27051 sched.cpp:407] Authenticating with
> master [email protected]:37345
> 00:35:26 I0930 00:35:26.360038 27048 slave.cpp:1028] Detecting new master
> 00:35:26 I0930 00:35:26.360064 27048 status_update_manager.cpp:177] Pausing
> sending status updates
> 00:35:26 I0930 00:35:26.360088 27051 sched.cpp:414] Using default CRAM-MD5
> authenticatee
> 00:35:26 I0930 00:35:26.360179 27051 authenticatee.cpp:121] Creating new
> client SASL connection
> 00:35:26 I0930 00:35:26.361390 27051 slave.cpp:1055] Authenticating with
> master [email protected]:37345
> 00:35:26 I0930 00:35:26.361455 27051 slave.cpp:1066] Using default CRAM-MD5
> authenticatee
> 00:35:26 I0930 00:35:26.361528 27051 master.cpp:7915] Authenticating
> [email protected]:37345
> 00:35:26 I0930 00:35:26.361593 27048 authenticatee.cpp:121] Creating new
> client SASL connection
> 00:35:26 I0930 00:35:26.362210 27051 authenticator.cpp:414] Starting
> authentication session for crammd5-authenticatee(527)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.362511 27051 authenticator.cpp:98] Creating new
> server SASL connection
> 00:35:26 I0930 00:35:26.362977 27048 master.cpp:7915] Authenticating
> slave(250)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.363024 27048 authenticator.cpp:414] Starting
> authentication session for crammd5-authenticatee(528)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.363075 27048 authenticator.cpp:98] Creating new
> server SASL connection
> 00:35:26 I0930 00:35:26.364542 27048 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> 00:35:26 I0930 00:35:26.364562 27048 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> 00:35:26 I0930 00:35:26.364598 27048 authenticator.cpp:204] Received SASL
> authentication start
> 00:35:26 I0930 00:35:26.364626 27048 authenticator.cpp:326] Authentication
> requires more steps
> 00:35:26 I0930 00:35:26.364655 27048 authenticatee.cpp:259] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.364689 27048 authenticator.cpp:232] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.364706 27048 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> 00:35:26 I0930 00:35:26.364713 27048 auxprop.cpp:181] Looking up auxiliary
> property '*userPassword'
> 00:35:26 I0930 00:35:26.364722 27048 auxprop.cpp:181] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> 00:35:26 I0930 00:35:26.364729 27048 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> 00:35:26 I0930 00:35:26.364753 27048 auxprop.cpp:131] Skipping auxiliary
> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.364759 27048 auxprop.cpp:131] Skipping auxiliary
> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.364770 27048 authenticator.cpp:318] Authentication
> success
> 00:35:26 I0930 00:35:26.364809 27048 authenticatee.cpp:299] Authentication
> success
> 00:35:26 I0930 00:35:26.364850 27048 master.cpp:7945] Successfully
> authenticated principal 'test-principal' at slave(250)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.364890 27048 authenticator.cpp:432] Authentication
> session cleanup for crammd5-authenticatee(528)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.364994 27048 slave.cpp:1150] Successfully
> authenticated with master [email protected]:37345
> 00:35:26 I0930 00:35:26.365178 27048 slave.cpp:1629] Will retry registration
> in 1ns if necessary
> 00:35:26 I0930 00:35:26.365453 27049 master.cpp:6137] Received re-register
> agent message from agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.365970 27048 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> 00:35:26 I0930 00:35:26.366021 27048 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> 00:35:26 I0930 00:35:26.366060 27048 authenticator.cpp:204] Received SASL
> authentication start
> 00:35:26 I0930 00:35:26.366088 27048 authenticator.cpp:326] Authentication
> requires more steps
> 00:35:26 I0930 00:35:26.366137 27048 authenticatee.cpp:259] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.366194 27048 authenticator.cpp:232] Received SASL
> authentication step
> 00:35:26 I0930 00:35:26.366224 27048 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> 00:35:26 I0930 00:35:26.366233 27048 auxprop.cpp:181] Looking up auxiliary
> property '*userPassword'
> 00:35:26 I0930 00:35:26.366242 27048 auxprop.cpp:181] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> 00:35:26 I0930 00:35:26.366250 27048 auxprop.cpp:109] Request to lookup
> properties for user: 'test-principal' realm: 'ip-172-16-10-150.ec2.internal'
> server FQDN: 'ip-172-16-10-150.ec2.internal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> 00:35:26 I0930 00:35:26.366256 27048 auxprop.cpp:131] Skipping auxiliary
> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.366261 27048 auxprop.cpp:131] Skipping auxiliary
> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> 00:35:26 I0930 00:35:26.366272 27048 authenticator.cpp:318] Authentication
> success
> 00:35:26 I0930 00:35:26.366312 27048 authenticatee.cpp:299] Authentication
> success
> 00:35:26 I0930 00:35:26.366376 27048 authenticator.cpp:432] Authentication
> session cleanup for crammd5-authenticatee(527)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.366461 27053 sched.cpp:513] Successfully
> authenticated with master [email protected]:37345
> 00:35:26 I0930 00:35:26.366477 27053 sched.cpp:836] Sending SUBSCRIBE call to
> [email protected]:37345
> 00:35:26 I0930 00:35:26.366505 27053 sched.cpp:869] Will retry registration
> in 1.626994719secs if necessary
> 00:35:26 terminate called after throwing an instance of 'std::system_error'
> 00:35:26 I0930 00:35:26.365510 27049 master.cpp:3856] Authorizing agent with
> principal 'test-principal'
> 00:35:26 I0930 00:35:26.366668 27049 master.cpp:7945] Successfully
> authenticated principal 'test-principal' at
> [email protected]:37345
> 00:35:26 I0930 00:35:26.366832 27048 master.cpp:6206] Authorized
> re-registration of agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.366865 27048 master.cpp:6342] Re-registering agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 W0930 00:35:26.367024 27048 master.hpp:2224] Allowing UNKNOWN agent
> to reregister: hostname: "ip-172-16-10-150"
> 00:35:26 resources {
> 00:35:26 name: "cpus"
> 00:35:26 type: SCALAR
> 00:35:26 scalar {
> 00:35:26 value: 2
> 00:35:26 }
> 00:35:26 role: "*"
> 00:35:26 }
> 00:35:26 resources {
> 00:35:26 name: "mem"
> 00:35:26 type: SCALAR
> 00:35:26 scalar {
> 00:35:26 value: 1024
> 00:35:26 }
> 00:35:26 role: "*"
> 00:35:26 }
> 00:35:26 resources {
> 00:35:26 name: "disk"
> 00:35:26 type: SCALAR
> 00:35:26 scalar {
> 00:35:26 value: 1024
> 00:35:26 }
> 00:35:26 role: "*"
> 00:35:26 }
> 00:35:26 resources {
> 00:35:26 name: "ports"
> 00:35:26 type: RANGES
> 00:35:26 ranges {
> 00:35:26 range {
> 00:35:26 begin: 31000
> 00:35:26 end: 32000
> 00:35:26 }
> 00:35:26 }
> 00:35:26 role: "*"
> 00:35:26 }
> 00:35:26 id {
> 00:35:26 value: "94ab36ee-4c02-457d-ae35-2f130ae826f5-S0"
> 00:35:26 }
> 00:35:26 checkpoint: true
> 00:35:26 port: 37345
> 00:35:26 I0930 00:35:26.367148 27048 registrar.cpp:495] Applied 1 operations
> in 127819ns; attempting to update the registry
> 00:35:26 I0930 00:35:26.367341 27048 registrar.cpp:552] Successfully updated
> the registry in 0ns
> 00:35:26 what(): Invalid argument
> 00:35:26 *** Aborted at 1506731726 (unix time) try "date -d @1506731726" if
> you are using GNU date ***
> 00:35:26 I0930 00:35:26.367468 27050 master.cpp:6411] Re-admitted agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.367744 27050 master.cpp:10114] Adding task 0 with
> resources
> [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":64.0},"type":"SCALAR"}]
> on agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.368002 27050 master.cpp:6589] Re-registered agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150) with
> [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> 00:35:26 PC: @ 0x7fd16a6e277f (unknown)
> 00:35:26 I*** SIGABRT (@0x6999) received by PID 27033 (TID 0x7fd160897700)
> from PID 27033; stack trace: ***
> 00:35:26 0930 00:35:26.368540 27050 master.cpp:6672] Recovering framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000 from re-registering agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at slave(250)@172.16.10.150:37345
> (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.368734 27050 master.cpp:6712] Sending updated
> checkpointed resources {} to agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150)
> 00:35:26 I0930 00:35:26.368178 27048 hierarchical.cpp:593] Added agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 (ip-172-16-10-150) with cpus:2;
> mem:1024; disk:1024; ports:[31000-32000] (allocated: cpus(allocated: *):1;
> mem(allocated: *):64)
> 00:35:26 I0930 00:35:26.369046 27048 hierarchical.cpp:303] Added framework
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.369061 27048 hierarchical.cpp:412] Deactivated
> framework 94ab36ee-4c02-457d-ae35-2f130ae826f5-0000
> 00:35:26 I0930 00:35:26.369098 27048 hierarchical.cpp:1943] No allocations
> performed
> 00:35:26 I0930 00:35:26.369107 27048 hierarchical.cpp:2033] No inverse offers
> to send out!
> 00:35:26 I0930 00:35:26.369114 27048 hierarchical.cpp:1486] Performed
> allocation for 1 agents in 35501ns
> 00:35:26 I0930 00:35:26.368240 27053 slave.cpp:1308] Re-registered with
> master [email protected]:37345
> 00:35:26 I0930 00:35:26.369191 27053 slave.cpp:1345] Forwarding total
> oversubscribed resources {}
> 00:35:26 I0930 00:35:26.369221 27053 slave.cpp:4969] Received ping from
> slave-observer(246)@172.16.10.150:37345
> 00:35:26 I0930 00:35:26.369246 27053 slave.cpp:3449] Ignoring new
> checkpointed resources identical to the current version: {}
> 00:35:26 I0930 00:35:26.369261 27053 status_update_manager.cpp:184] Resuming
> sending status updates
> 00:35:26 I0930 00:35:26.369282 27053 master.cpp:6814] Received update of
> agent 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 at
> slave(250)@172.16.10.150:37345 (ip-172-16-10-150) with total oversubscribed
> resources {}
> 00:35:26 I0930 00:35:26.369340 27053 hierarchical.cpp:660] Agent
> 94ab36ee-4c02-457d-ae35-2f130ae826f5-S0 (ip-172-16-10-150) updated with total
> resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> 00:35:26 @ 0x7fd16aa85670 (unknown)
> 00:35:26 @ 0x7fd16a6e277f (unknown)
> 00:35:26 @ 0x7fd16a6e437a (unknown)
> 00:35:26 @ 0x7fd16b24356d (unknown)
> 00:35:26 @ 0x7fd16b241316 (unknown)
> 00:35:26 @ 0x7fd16b241361 (unknown)
> 00:35:26 @ 0x7fd16b26d86e (unknown)
> 00:35:26 @ 0x7fd16aa7b6da start_thread
> 00:35:26 @ 0x7fd16a7b5d7f (unknown)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
