You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Alexander Rukletsov (JIRA)" <ji...@apache.org> on 2017/11/09 19:14:01 UTC
[jira] [Updated] (MESOS-8049) MasterTest.RecoveredFramework is
flaky and crashes.
[ 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 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)