Till Toenshoff created MESOS-8049:
-------------------------------------
Summary: 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
{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 files@172.16.10.150: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 version@172.16.10.150: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
master@172.16.10.150: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
master@172.16.10.150:37345
00:35:26 I0930 00:35:26.329989 27052 sched.cpp:407] Authenticating with master
master@172.16.10.150: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
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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 master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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 master@172.16.10.150:37345
00:35:26 I0930 00:35:26.335862 27048 sched.cpp:836] Sending SUBSCRIBE call to
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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 scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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 version@172.16.10.150: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
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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
master@172.16.10.150: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
master@172.16.10.150:37345
00:35:26 I0930 00:35:26.360000 27048 slave.cpp:993] New master detected at
master@172.16.10.150:37345
00:35:26 I0930 00:35:26.360007 27051 sched.cpp:407] Authenticating with master
master@172.16.10.150: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
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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 master@172.16.10.150: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 master@172.16.10.150:37345
00:35:26 I0930 00:35:26.366477 27053 sched.cpp:836] Sending SUBSCRIBE call to
master@172.16.10.150: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
scheduler-107e6025-f128-4cc6-a96a-df8ab83ed66c@172.16.10.150: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
master@172.16.10.150: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)
