Jan Schlicht created MESOS-8289:
-----------------------------------
Summary: ReservationTest.MasterFailover is flaky when run with
`RESOURCE_PROVIDER` capability
Key: MESOS-8289
URL: https://issues.apache.org/jira/browse/MESOS-8289
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Jan Schlicht
Assignee: Jan Schlicht
Fix For: 1.5.0
On a system under load,
{{ResourceProviderCapability/ReservationTest.MasterFailover/1}} can fail.
{{GLOG_v=2}} of the failure:
{noformat}
[ RUN ] ResourceProviderCapability/ReservationTest.MasterFailover/1
I1201 14:52:47.324741 122806272 process.cpp:2730] Dropping event for process
hierarchical-allocator(34)@172.18.8.37:57116
I1201 14:52:47.324816 122806272 process.cpp:2730] Dropping event for process
slave(17)@172.18.8.37:57116
I1201 14:52:47.324859 2720961344 clock.cpp:331] Clock paused at 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.326314 2720961344 clock.cpp:435] Clock of
files@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.326371 2720961344 clock.cpp:435] Clock of
hierarchical-allocator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.326539 2720961344 cluster.cpp:170] Creating default 'local'
authorizer
I1201 14:52:47.326568 2720961344 clock.cpp:435] Clock of
local-authorizer(52)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.326671 2720961344 clock.cpp:435] Clock of
standalone-master-detector(52)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.326709 2720961344 clock.cpp:435] Clock of
in-memory-storage(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.326884 2720961344 clock.cpp:435] Clock of
registrar(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.327579 2720961344 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.330301 119050240 master.cpp:454] Master
209387ca-a9c3-4717-9769-a59d9fe927f1 (172.18.8.37) started on 172.18.8.37:57116
I1201 14:52:47.330329 119050240 master.cpp:456] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="5ms" --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="/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/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" --roles="role"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/master"
--zk_session_timeout="10secs"
I1201 14:52:47.330628 119050240 master.cpp:505] Master only allowing
authenticated frameworks to register
I1201 14:52:47.330638 119050240 master.cpp:511] Master only allowing
authenticated agents to register
I1201 14:52:47.330644 119050240 master.cpp:517] Master only allowing
authenticated HTTP frameworks to register
I1201 14:52:47.330652 119050240 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/credentials'
I1201 14:52:47.330873 119050240 master.cpp:561] Using default 'crammd5'
authenticator
I1201 14:52:47.330927 119050240 clock.cpp:435] Clock of
crammd5-authenticator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.330963 119050240 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1201 14:52:47.330993 119050240 clock.cpp:435] Clock of
__basic_authenticator__(137)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.331056 119050240 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1201 14:52:47.331082 119050240 clock.cpp:435] Clock of
__basic_authenticator__(138)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.331151 119050240 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1201 14:52:47.331176 119050240 clock.cpp:435] Clock of
__basic_authenticator__(139)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.331228 119050240 master.cpp:640] Authorization enabled
W1201 14:52:47.331238 119050240 master.cpp:703] The '--roles' flag is
deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade
notes for more information
I1201 14:52:47.331326 119050240 clock.cpp:435] Clock of
whitelist(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.331521 118513664 hierarchical.cpp:173] Initialized hierarchical
allocator process
I1201 14:52:47.331560 122269696 whitelist_watcher.cpp:77] No whitelist given
I1201 14:52:47.333322 119050240 master.cpp:2221] Elected as the leading master!
I1201 14:52:47.333339 119050240 master.cpp:1701] Recovering from registrar
I1201 14:52:47.333454 120659968 registrar.cpp:347] Recovering registrar
I1201 14:52:47.333526 120659968 clock.cpp:435] Clock of
__latch__(154)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.333732 120659968 registrar.cpp:391] Successfully fetched the
registry (0B) in 0ns
I1201 14:52:47.333809 120659968 registrar.cpp:495] Applied 1 operations in
29366ns; attempting to update the registry
I1201 14:52:47.333927 120659968 clock.cpp:435] Clock of
__latch__(155)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.334156 118513664 registrar.cpp:552] Successfully updated the
registry in 0ns
I1201 14:52:47.334218 118513664 registrar.cpp:424] Successfully recovered
registrar
I1201 14:52:47.334426 119050240 master.cpp:1814] Recovered 0 agents from the
registry (131B); allowing 10mins for agents to re-register
I1201 14:52:47.334503 119586816 hierarchical.cpp:211] Skipping recovery of
hierarchical allocator: nothing to recover
I1201 14:52:47.337247 2720961344 clock.cpp:435] Clock of
standalone-master-detector(53)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.338493 2720961344 clock.cpp:435] Clock of
files@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
W1201 14:52:47.338521 2720961344 process.cpp:2756] Attempted to spawn already
running process files@172.18.8.37:57116
I1201 14:52:47.338845 2720961344 clock.cpp:435] Clock of
fetcher(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.339238 2720961344 containerizer.cpp:304] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I1201 14:52:47.339455 2720961344 clock.cpp:435] Clock of
copy-provisioner-backend(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.339504 2720961344 provisioner.cpp:297] Using default backend
'copy'
I1201 14:52:47.339524 2720961344 clock.cpp:435] Clock of
mesos-provisioner(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.339607 2720961344 clock.cpp:435] Clock of
environment-secret-isolator(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.339789 2720961344 clock.cpp:435] Clock of
posix-filesystem-isolator(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.339973 2720961344 clock.cpp:435] Clock of
posix-mem-isolator(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340020 2720961344 clock.cpp:435] Clock of
posix-cpu-isolator(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340062 2720961344 clock.cpp:435] Clock of
sandbox-logger(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340103 2720961344 clock.cpp:435] Clock of (18)@172.18.8.37:57116
updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.340281 2720961344 clock.cpp:435] Clock of
mesos-containerizer(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340481 2720961344 cluster.cpp:458] Creating default 'local'
authorizer
I1201 14:52:47.340513 2720961344 clock.cpp:435] Clock of
local-authorizer(53)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340608 2720961344 clock.cpp:435] Clock of
agent-garbage-collector(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340742 2720961344 clock.cpp:435] Clock of
__executor__(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.340839 2720961344 clock.cpp:435] Clock of
task-status-update-manager(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.341027 2720961344 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.341190 2720961344 clock.cpp:435] Clock of
__limiter__(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.341687 2720961344 clock.cpp:435] Clock of
resource-provider-manager(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.341840 121196544 slave.cpp:253] Mesos agent started on
(18)@172.18.8.37:57116
I1201 14:52:47.341935 2720961344 clock.cpp:381] Clock advanced (10ms) to
2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.342027 122806272 clock.cpp:435] Clock of
hierarchical-allocator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.839857088+00:00
I1201 14:52:47.342051 122806272 clock.cpp:435] Clock of
__reaper__(1)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.842657088+00:00
I1201 14:52:47.341878 121196544 slave.cpp:254] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/store/appc"
--authenticate_http_readonly="true" --authenticate_http_readwrite="true"
--authenticatee="crammd5" --authentication_backoff_factor="1secs"
--authorizer="local" --container_disk_watch_interval="15secs"
--containerizers="mesos"
--credential="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns"
--docker_store_dir="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/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="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/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="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/Users/jan/Documents/mesos/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:8;mem:2048"
--runtime_dir="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_wjKAB3"
--zk_session_timeout="10secs"
I1201 14:52:47.342082 122806272 clock.cpp:435] Clock of
hierarchical-allocator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.342172 121196544 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/credential'
I1201 14:52:47.342216 122806272 clock.cpp:435] Clock of
__reaper__(1)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.342301 121196544 slave.cpp:286] Agent using credential for:
test-principal
I1201 14:52:47.342316 121196544 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_DhNV1G/http_credentials'
I1201 14:52:47.342391 120659968 hierarchical.cpp:1890] No allocations performed
I1201 14:52:47.342411 120659968 hierarchical.cpp:1431] Performed allocation for
0 agents in 45088ns
I1201 14:52:47.342497 121196544 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1201 14:52:47.342541 121196544 clock.cpp:435] Clock of
__basic_authenticator__(140)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.342600 121196544 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1201 14:52:47.342628 121196544 clock.cpp:435] Clock of
__basic_authenticator__(141)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.342682 121196544 clock.cpp:435] Clock of
noop-resource-estimator(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.342725 121196544 clock.cpp:435] Clock of
qos-noop-controller(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.342804 121196544 clock.cpp:435] Clock of
local-resource-provider-daemon(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.343531 121196544 slave.cpp:585] Agent resources:
[{"name":"cpus","scalar":{"value":8.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":2048.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":470537.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1201 14:52:47.343757 121196544 slave.cpp:593] Agent attributes: [ ]
I1201 14:52:47.343766 121196544 slave.cpp:602] Agent hostname: 172.18.8.37
I1201 14:52:47.343842 119050240 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1201 14:52:47.344367 121196544 clock.cpp:435] Clock of
__async_executor__(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.834857088+00:00
I1201 14:52:47.344763 122269696 state.cpp:64] Recovering state from
'/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_wjKAB3/meta'
I1201 14:52:47.344969 120123392 task_status_update_manager.cpp:207] Recovering
task status update manager
I1201 14:52:47.345077 119050240 containerizer.cpp:672] Recovering containerizer
I1201 14:52:47.345255 119050240 clock.cpp:435] Clock of
__collect__(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.345836 119050240 clock.cpp:435] Clock of
__collect__(36)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.834857088+00:00
I1201 14:52:47.345984 119586816 provisioner.cpp:493] Provisioner recovery
complete
I1201 14:52:47.346258 121196544 slave.cpp:6513] Finished recovery
I1201 14:52:47.353896 121196544 slave.cpp:6701] Querying resource estimator for
oversubscribable resources
I1201 14:52:47.354270 120123392 slave.cpp:999] New master detected at
master@172.18.8.37:57116
I1201 14:52:47.354349 120123392 slave.cpp:1034] Detecting new master
I1201 14:52:47.354396 120123392 slave.cpp:6715] Received oversubscribable
resources {} from the resource estimator
I1201 14:52:47.354427 119586816 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1201 14:52:47.354418 122806272 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844058370+00:00
I1201 14:52:47.354485 122806272 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.354533 122269696 slave.cpp:1061] Authenticating with master
master@172.18.8.37:57116
I1201 14:52:47.354569 122269696 slave.cpp:1070] Using default CRAM-MD5
authenticatee
I1201 14:52:47.354616 122269696 clock.cpp:435] Clock of
crammd5-authenticatee(69)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.354712 121733120 authenticatee.cpp:121] Creating new client SASL
connection
I1201 14:52:47.354758 121733120 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.354904 121196544 master.cpp:8589] Authenticating
slave(18)@172.18.8.37:57116
I1201 14:52:47.354948 121196544 clock.cpp:435] Clock of
crammd5-authenticator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.355032 120659968 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(69)@172.18.8.37:57116
I1201 14:52:47.355062 120659968 clock.cpp:435] Clock of
crammd5-authenticator-session(69)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.355201 118513664 authenticator.cpp:98] Creating new server SASL
connection
I1201 14:52:47.355330 119586816 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1201 14:52:47.355350 119586816 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1201 14:52:47.355409 119050240 authenticator.cpp:204] Received SASL
authentication start
I1201 14:52:47.355455 119050240 authenticator.cpp:326] Authentication requires
more steps
I1201 14:52:47.355516 120123392 authenticatee.cpp:259] Received SASL
authentication step
I1201 14:52:47.355592 122269696 authenticator.cpp:232] Received SASL
authentication step
I1201 14:52:47.355625 122269696 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1201 14:52:47.355651 122269696 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1201 14:52:47.355687 122269696 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1201 14:52:47.355713 122269696 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1201 14:52:47.355736 122269696 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.355758 122269696 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.355783 122269696 authenticator.cpp:318] Authentication success
I1201 14:52:47.355907 121733120 master.cpp:8619] Successfully authenticated
principal 'test-principal' at slave(18)@172.18.8.37:57116
I1201 14:52:47.355965 121196544 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(69)@172.18.8.37:57116
I1201 14:52:47.355998 120659968 authenticatee.cpp:299] Authentication success
I1201 14:52:47.356014 121196544 clock.cpp:435] Clock of help@172.18.8.37:57116
updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.356144 119050240 slave.cpp:1153] Successfully authenticated with
master master@172.18.8.37:57116
I1201 14:52:47.356294 119050240 slave.cpp:1696] Will retry registration in
2.9532ms if necessary
I1201 14:52:47.356449 121733120 master.cpp:6042] Received register agent
message from slave(18)@172.18.8.37:57116 (172.18.8.37)
I1201 14:52:47.356472 121733120 master.cpp:3878] Authorizing agent with
principal 'test-principal'
I1201 14:52:47.356495 121733120 clock.cpp:435] Clock of
local-authorizer(52)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.356734 120659968 master.cpp:6104] Authorized registration of
agent at slave(18)@172.18.8.37:57116 (172.18.8.37)
I1201 14:52:47.356797 120659968 master.cpp:6197] Registering agent at
slave(18)@172.18.8.37:57116 (172.18.8.37) with id
209387ca-a9c3-4717-9769-a59d9fe927f1-S0
I1201 14:52:47.356842 120659968 clock.cpp:435] Clock of
registrar(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.357019 121196544 registrar.cpp:495] Applied 1 operations in
51305ns; attempting to update the registry
I1201 14:52:47.357128 121196544 clock.cpp:435] Clock of
in-memory-storage(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.357218 121196544 clock.cpp:435] Clock of
__latch__(156)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.357378 121196544 registrar.cpp:552] Successfully updated the
registry in 0ns
I1201 14:52:47.357507 119050240 master.cpp:6246] Admitted agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.357703 119050240 clock.cpp:435] Clock of
slave-observer(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.357873 120659968 slave.cpp:5160] Received ping from
slave-observer(35)@172.18.8.37:57116
I1201 14:52:47.357844 119050240 master.cpp:6282] Registered agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with cpus:8; mem:2048; disk:470537; ports:[31000-32000]
I1201 14:52:47.357964 120659968 slave.cpp:1199] Registered with master
master@172.18.8.37:57116; given agent ID 209387ca-a9c3-4717-9769-a59d9fe927f1-S0
I1201 14:52:47.357992 120659968 clock.cpp:435] Clock of
task-status-update-manager(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.358054 122269696 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1201 14:52:47.358053 118513664 hierarchical.cpp:553] Added agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 (172.18.8.37) with cpus:8; mem:2048;
disk:470537; ports:[31000-32000] (allocated: {})
I1201 14:52:47.358266 118513664 hierarchical.cpp:1890] No allocations performed
I1201 14:52:47.358304 118513664 hierarchical.cpp:1431] Performed allocation for
1 agents in 118185ns
I1201 14:52:47.358395 120659968 slave.cpp:1219] Checkpointing SlaveInfo to
'/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/ResourceProviderCapability_ReservationTest_MasterFailover_1_wjKAB3/meta/slaves/209387ca-a9c3-4717-9769-a59d9fe927f1-S0/slave.info'
I1201 14:52:47.358955 120659968 clock.cpp:435] Clock of
local-resource-provider-daemon(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.359042 120659968 slave.cpp:1281] Forwarding total resources
cpus:8; mem:2048; disk:470537; ports:[31000-32000]
I1201 14:52:47.359097 120659968 slave.cpp:1298] Forwarding total oversubscribed
resources {}
I1201 14:52:47.359454 121196544 master.cpp:7036] Received update of agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with total resources cpus:8; mem:2048; disk:470537;
ports:[31000-32000]
I1201 14:52:47.359508 121196544 master.cpp:7049] Received update of agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with total oversubscribed resources {}
I1201 14:52:47.359946 121733120 hierarchical.cpp:620] Agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 (172.18.8.37) updated with total
resources cpus:8; mem:2048; disk:470537; ports:[31000-32000]
I1201 14:52:47.361738 2720961344 clock.cpp:435] Clock of
version@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
W1201 14:52:47.361764 2720961344 process.cpp:2756] Attempted to spawn already
running process version@172.18.8.37:57116
I1201 14:52:47.361790 2720961344 clock.cpp:435] Clock of
__latch__(157)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.366130 2720961344 clock.cpp:435] Clock of
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116 updated to
2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.366179 2720961344 clock.cpp:435] Clock of
metrics@172.18.8.37:57116 updated to 2017-12-01 13:53:04.844857088+00:00
I1201 14:52:47.366233 2720961344 sched.cpp:232] Version: 1.5.0
I1201 14:52:47.366262 2720961344 clock.cpp:381] Clock advanced (5ms) to
2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.366351 122806272 clock.cpp:435] Clock of
hierarchical-allocator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.366603 118513664 clock.cpp:435] Clock of
standalone-master-detector(53)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.366729 122269696 hierarchical.cpp:1890] No allocations performed
I1201 14:52:47.366744 120123392 sched.cpp:336] New master detected at
master@172.18.8.37:57116
I1201 14:52:47.366755 122269696 hierarchical.cpp:1431] Performed allocation for
1 agents in 84509ns
I1201 14:52:47.366794 120123392 sched.cpp:396] Authenticating with master
master@172.18.8.37:57116
I1201 14:52:47.366806 120123392 sched.cpp:403] Using default CRAM-MD5
authenticatee
I1201 14:52:47.366844 120123392 clock.cpp:435] Clock of
crammd5-authenticatee(70)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.366993 121196544 authenticatee.cpp:121] Creating new client SASL
connection
I1201 14:52:47.367127 119050240 master.cpp:8589] Authenticating
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.367199 119586816 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(70)@172.18.8.37:57116
I1201 14:52:47.367228 119586816 clock.cpp:435] Clock of
crammd5-authenticator-session(70)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.844857088+00:00
I1201 14:52:47.367327 118513664 authenticator.cpp:98] Creating new server SASL
connection
I1201 14:52:47.367401 120659968 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1201 14:52:47.367424 120659968 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1201 14:52:47.367471 122269696 authenticator.cpp:204] Received SASL
authentication start
I1201 14:52:47.367512 122269696 authenticator.cpp:326] Authentication requires
more steps
I1201 14:52:47.367568 120123392 authenticatee.cpp:259] Received SASL
authentication step
I1201 14:52:47.367624 121733120 authenticator.cpp:232] Received SASL
authentication step
I1201 14:52:47.367642 121733120 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1201 14:52:47.367652 121733120 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1201 14:52:47.367668 121733120 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1201 14:52:47.367678 121733120 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1201 14:52:47.367688 121733120 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.367694 121733120 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.367704 121733120 authenticator.cpp:318] Authentication success
I1201 14:52:47.367748 121196544 authenticatee.cpp:299] Authentication success
I1201 14:52:47.367775 119586816 master.cpp:8619] Successfully authenticated
principal 'test-principal' at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.367806 118513664 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(70)@172.18.8.37:57116
I1201 14:52:47.367884 119050240 sched.cpp:502] Successfully authenticated with
master master@172.18.8.37:57116
I1201 14:52:47.367899 119050240 sched.cpp:824] Sending SUBSCRIBE call to
master@172.18.8.37:57116
I1201 14:52:47.367959 119050240 sched.cpp:857] Will retry registration in
1.762124339secs if necessary
I1201 14:52:47.368059 121733120 master.cpp:2969] Received SUBSCRIBE call for
framework 'default' at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.368075 121733120 master.cpp:2286] Authorizing framework
principal 'test-principal' to receive offers for roles '{ role }'
I1201 14:52:47.368321 119586816 master.cpp:3049] Subscribing framework default
with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
I1201 14:52:47.368604 120659968 clock.cpp:435] Clock of
metrics@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.368692 120659968 hierarchical.cpp:293] Added framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.368717 120123392 sched.cpp:751] Framework registered with
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.368772 120123392 sched.cpp:765] Scheduler::registered took
45597ns
I1201 14:52:47.368937 120659968 hierarchical.cpp:1860] Allocating cpus:8;
mem:2048; disk:470537; ports:[31000-32000] on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 to role role of framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.369276 120659968 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.369351 120659968 hierarchical.cpp:1990] No inverse offers to
send out!
I1201 14:52:47.369380 120659968 hierarchical.cpp:1431] Performed allocation for
1 agents in 643932ns
I1201 14:52:47.369691 119050240 master.cpp:8419] Sending 1 offers to framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (default) at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.369753 119050240 clock.cpp:435] Clock of
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116 updated to
2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.369946 121733120 sched.cpp:897] Received 1 offers
I1201 14:52:47.370076 121733120 sched.cpp:921] Scheduler::resourceOffers took
82264ns
I1201 14:52:47.372522 119586816 master.cpp:10331] Removing offer
209387ca-a9c3-4717-9769-a59d9fe927f1-O0
I1201 14:52:47.372608 119586816 master.cpp:4236] Processing ACCEPT call for
offers: [ 209387ca-a9c3-4717-9769-a59d9fe927f1-O0 ] on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) for framework 209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (default)
at scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.372666 119586816 clock.cpp:435] Clock of
local-authorizer(52)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.372692 119586816 master.cpp:3663] Authorizing principal
'test-principal' to reserve resources
'[{"allocation_info":{"role":"role"},"name":"cpus","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":8.0},"type":"SCALAR"},{"allocation_info":{"role":"role"},"name":"mem","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I1201 14:52:47.373001 119586816 clock.cpp:435] Clock of
__await__(52)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.373103 119586816 clock.cpp:435] Clock of
__await__(53)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.373265 118513664 clock.cpp:435] Clock of help@172.18.8.37:57116
updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.373839 119050240 master.cpp:4569] Applying RESERVE operation for
resources
[{"allocation_info":{"role":"role"},"name":"cpus","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":8.0},"type":"SCALAR"},{"allocation_info":{"role":"role"},"name":"mem","reservations":[{"principal":"test-principal","role":"role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]
from framework 209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (default) at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116 to agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.374579 119050240 master.cpp:10228] Sending offer operation ''
(uuid: 06473b15-dc7c-4e97-8a36-11798b6ad430) to agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.374627 119050240 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.376063 121196544 slave.cpp:3605] Updated checkpointed resources
from {} to cpus(reservations: [(DYNAMIC,role,test-principal)]):8;
mem(reservations: [(DYNAMIC,role,test-principal)]):2048
I1201 14:52:47.376122 121196544 slave.cpp:7079] Updating the state of offer
operation '' (uuid: 06473b15-dc7c-4e97-8a36-11798b6ad430) of framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (latest state:
OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
I1201 14:52:47.376248 118513664 master.cpp:10015] Updating the state of offer
operation '' (uuid: 06473b15-dc7c-4e97-8a36-11798b6ad430) of framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (latest state:
OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
I1201 14:52:47.376736 122269696 hierarchical.cpp:830] Updated allocation of
framework 209387ca-a9c3-4717-9769-a59d9fe927f1-0000 on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 from cpus(allocated: role):8;
mem(allocated: role):2048; disk(allocated: role):470537; ports(allocated:
role):[31000-32000] to ports(allocated: role):[31000-32000]; cpus(allocated:
role)(reservations: [(DYNAMIC,role,test-principal)]):8; disk(allocated:
role):470537; mem(allocated: role)(reservations:
[(DYNAMIC,role,test-principal)]):2048
I1201 14:52:47.377378 122269696 hierarchical.cpp:1106] Recovered
ports(allocated: role):[31000-32000]; cpus(allocated: role)(reservations:
[(DYNAMIC,role,test-principal)]):8; disk(allocated: role):470537;
mem(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):2048
(total: ports:[31000-32000]; cpus(reservations:
[(DYNAMIC,role,test-principal)]):8; disk:470537; mem(reservations:
[(DYNAMIC,role,test-principal)]):2048, allocated: {}) on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 from framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.377565 2720961344 clock.cpp:435] Clock of
__authentication_router__(1)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.377607 2720961344 master.cpp:1159] Master terminating
I1201 14:52:47.377635 120659968 clock.cpp:435] Clock of
__basic_authenticator__(137)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.377753 2720961344 clock.cpp:435] Clock of
slave-observer(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.377820 120659968 clock.cpp:435] Clock of
__basic_authenticator__(138)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.377976 2720961344 clock.cpp:435] Clock of
whitelist(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.378032 2720961344 clock.cpp:435] Clock of
crammd5-authenticator(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.378087 121733120 hierarchical.cpp:586] Removed agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0
I1201 14:52:47.378192 121733120 hierarchical.cpp:345] Removed framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.378202 120123392 slave.cpp:5202] Got exited event for
master@172.18.8.37:57116
W1201 14:52:47.378216 120123392 slave.cpp:5207] Master disconnected! Waiting
for a new master to be elected
I1201 14:52:47.378964 2720961344 clock.cpp:435] Clock of
registrar(35)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.379283 2720961344 clock.cpp:435] Clock of
in-memory-storage(35)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.379336 2720961344 clock.cpp:435] Clock of
standalone-master-detector(52)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.379380 2720961344 process.cpp:2730] Dropping event for process
master@172.18.8.37:57116
I1201 14:52:47.379434 2720961344 process.cpp:2730] Dropping event for process
master@172.18.8.37:57116
I1201 14:52:47.379631 2720961344 clock.cpp:435] Clock of
files@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.379984 2720961344 clock.cpp:435] Clock of
files@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.380062 2720961344 clock.cpp:435] Clock of
hierarchical-allocator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.380225 2720961344 cluster.cpp:170] Creating default 'local'
authorizer
I1201 14:52:47.380254 2720961344 clock.cpp:435] Clock of
local-authorizer(54)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.380331 2720961344 clock.cpp:435] Clock of
standalone-master-detector(54)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.380364 2720961344 clock.cpp:435] Clock of
in-memory-storage(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.380398 2720961344 clock.cpp:435] Clock of
registrar(36)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.380887 2720961344 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.382493 121733120 master.cpp:454] Master
2cadeec8-e39c-486b-bcd9-c24721e36b5a (172.18.8.37) started on 172.18.8.37:57116
I1201 14:52:47.382514 121733120 master.cpp:456] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="5ms" --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="/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/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" --roles="role"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/master"
--zk_session_timeout="10secs"
I1201 14:52:47.382732 121733120 master.cpp:505] Master only allowing
authenticated frameworks to register
I1201 14:52:47.382743 121733120 master.cpp:511] Master only allowing
authenticated agents to register
I1201 14:52:47.382750 121733120 master.cpp:517] Master only allowing
authenticated HTTP frameworks to register
I1201 14:52:47.382756 121733120 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/0b/srgwj7vd2037pygpz1fpyqgm0000gn/T/z44iHn/credentials'
I1201 14:52:47.382990 121733120 master.cpp:561] Using default 'crammd5'
authenticator
I1201 14:52:47.383054 121733120 clock.cpp:435] Clock of
crammd5-authenticator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.383100 121733120 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1201 14:52:47.383141 121733120 clock.cpp:435] Clock of
__basic_authenticator__(142)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.383208 121733120 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1201 14:52:47.383245 121733120 clock.cpp:435] Clock of
__basic_authenticator__(143)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.383299 121733120 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1201 14:52:47.383329 121733120 clock.cpp:435] Clock of
__basic_authenticator__(144)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.383373 121733120 master.cpp:640] Authorization enabled
W1201 14:52:47.383383 121733120 master.cpp:703] The '--roles' flag is
deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade
notes for more information
I1201 14:52:47.383452 122269696 clock.cpp:435] Clock of
__basic_authenticator__(139)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.383494 121733120 clock.cpp:435] Clock of
whitelist(36)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.383536 119050240 hierarchical.cpp:173] Initialized hierarchical
allocator process
I1201 14:52:47.383571 119586816 whitelist_watcher.cpp:77] No whitelist given
I1201 14:52:47.385560 119050240 master.cpp:2221] Elected as the leading master!
I1201 14:52:47.385589 119050240 master.cpp:1701] Recovering from registrar
I1201 14:52:47.385844 119586816 registrar.cpp:347] Recovering registrar
I1201 14:52:47.385941 119586816 clock.cpp:435] Clock of
__latch__(158)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.386288 119050240 registrar.cpp:391] Successfully fetched the
registry (0B) in 0ns
I1201 14:52:47.386355 119050240 registrar.cpp:495] Applied 1 operations in
25658ns; attempting to update the registry
I1201 14:52:47.386454 119050240 clock.cpp:435] Clock of
__latch__(159)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.849857088+00:00
I1201 14:52:47.386924 120123392 registrar.cpp:552] Successfully updated the
registry in 0ns
I1201 14:52:47.387053 120123392 registrar.cpp:424] Successfully recovered
registrar
I1201 14:52:47.387351 118513664 master.cpp:1814] Recovered 0 agents from the
registry (131B); allowing 10mins for agents to re-register
I1201 14:52:47.387539 119050240 hierarchical.cpp:211] Skipping recovery of
hierarchical allocator: nothing to recover
I1201 14:52:47.389255 2720961344 clock.cpp:435] Clock of
standalone-master-detector(53)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.389283 2720961344 clock.cpp:381] Clock advanced (1secs) to
2017-12-01 13:53:05.849857088+00:00
I1201 14:52:47.389328 2720961344 clock.cpp:381] Clock advanced (10ms) to
2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.389621 122806272 clock.cpp:435] Clock of
hierarchical-allocator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.854857088+00:00
I1201 14:52:47.389695 122806272 clock.cpp:435] Clock of
__reaper__(1)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.944857088+00:00
I1201 14:52:47.389721 122806272 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:05.121836864+00:00
I1201 14:52:47.389757 122806272 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:05.223129856+00:00
I1201 14:52:47.389801 122806272 process.cpp:2730] Dropping event for process
hierarchical-allocator(35)@172.18.8.37:57116
I1201 14:52:47.389827 122269696 sched.cpp:330] Scheduler::disconnected took
26933ns
I1201 14:52:47.389847 122269696 sched.cpp:336] New master detected at
master@172.18.8.37:57116
I1201 14:52:47.389847 119586816 clock.cpp:435] Clock of
task-status-update-manager(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.389878 122806272 clock.cpp:435] Clock of
hierarchical-allocator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.389904 119586816 slave.cpp:999] New master detected at
master@172.18.8.37:57116
I1201 14:52:47.389920 122806272 clock.cpp:435] Clock of
__reaper__(1)@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.389943 118513664 task_status_update_manager.cpp:181] Pausing
sending task status updates
I1201 14:52:47.389977 122269696 sched.cpp:396] Authenticating with master
master@172.18.8.37:57116
I1201 14:52:47.389991 122269696 sched.cpp:403] Using default CRAM-MD5
authenticatee
I1201 14:52:47.390002 119586816 slave.cpp:1034] Detecting new master
I1201 14:52:47.390007 122806272 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.390041 122806272 process.cpp:2730] Dropping event for process
slave(13)@172.18.8.37:57116
I1201 14:52:47.390142 122269696 clock.cpp:435] Clock of
crammd5-authenticatee(71)@172.18.8.37:57116 updated to 2017-12-01
13:53:04.849857088+00:00
I1201 14:52:47.390215 122806272 process.cpp:2730] Dropping event for process
slave-observer(8)@172.18.8.37:57116
I1201 14:52:47.390233 122806272 process.cpp:2730] Dropping event for process
slave(14)@172.18.8.37:57116
I1201 14:52:47.390305 122806272 process.cpp:2730] Dropping event for process
scheduler-43385646-c98e-467a-85bf-bf2dde2554e3@172.18.8.37:57116
I1201 14:52:47.390333 119586816 authenticatee.cpp:121] Creating new client SASL
connection
I1201 14:52:47.390377 120123392 hierarchical.cpp:1890] No allocations performed
I1201 14:52:47.390394 122806272 process.cpp:2730] Dropping event for process
scheduler-43385646-c98e-467a-85bf-bf2dde2554e3@172.18.8.37:57116
I1201 14:52:47.390410 122806272 process.cpp:2730] Dropping event for process
slave(5)@172.18.8.37:57116
I1201 14:52:47.390422 122806272 process.cpp:2730] Dropping event for process
slave-observer(9)@172.18.8.37:57116
I1201 14:52:47.390434 122806272 process.cpp:2730] Dropping event for process
scheduler-adf2755a-1205-4709-b112-20b68b416d29@172.18.8.37:57116
I1201 14:52:47.390486 120659968 master.cpp:8589] Authenticating
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.390480 120123392 hierarchical.cpp:1431] Performed allocation for
0 agents in 143584ns
I1201 14:52:47.390514 120659968 clock.cpp:435] Clock of
crammd5-authenticator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.390588 118513664 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(71)@172.18.8.37:57116
I1201 14:52:47.390600 122806272 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:04.856267893+00:00
I1201 14:52:47.390712 118513664 clock.cpp:435] Clock of
crammd5-authenticator-session(71)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.390739 122806272 clock.cpp:435] Clock of
slave(18)@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.390795 121733120 slave.cpp:1061] Authenticating with master
master@172.18.8.37:57116
I1201 14:52:47.390843 121196544 authenticator.cpp:98] Creating new server SASL
connection
I1201 14:52:47.390856 121733120 slave.cpp:1070] Using default CRAM-MD5
authenticatee
I1201 14:52:47.390898 121733120 clock.cpp:435] Clock of
crammd5-authenticatee(72)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.390928 121196544 clock.cpp:435] Clock of
crammd5-authenticatee(71)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.391010 119586816 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1201 14:52:47.391033 119586816 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1201 14:52:47.391055 122269696 authenticatee.cpp:121] Creating new client SASL
connection
I1201 14:52:47.391096 119050240 authenticator.cpp:204] Received SASL
authentication start
I1201 14:52:47.391152 119050240 authenticator.cpp:326] Authentication requires
more steps
I1201 14:52:47.391176 120123392 master.cpp:8589] Authenticating
slave(18)@172.18.8.37:57116
I1201 14:52:47.391217 120659968 authenticatee.cpp:259] Received SASL
authentication step
I1201 14:52:47.391259 118513664 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(72)@172.18.8.37:57116
I1201 14:52:47.391302 121196544 authenticator.cpp:232] Received SASL
authentication step
I1201 14:52:47.391297 118513664 clock.cpp:435] Clock of
crammd5-authenticator-session(72)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.391327 121196544 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1201 14:52:47.391341 121196544 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1201 14:52:47.391372 121196544 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1201 14:52:47.391384 121196544 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1201 14:52:47.391394 121196544 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.391400 121196544 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.391412 121196544 authenticator.cpp:318] Authentication success
I1201 14:52:47.391432 121733120 authenticator.cpp:98] Creating new server SASL
connection
I1201 14:52:47.391477 119586816 authenticatee.cpp:299] Authentication success
I1201 14:52:47.391510 119586816 clock.cpp:435] Clock of
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116 updated to
2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.391515 122269696 master.cpp:8619] Successfully authenticated
principal 'test-principal' at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.391571 119050240 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(71)@172.18.8.37:57116
I1201 14:52:47.391602 120123392 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I1201 14:52:47.391620 120123392 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I1201 14:52:47.391645 119050240 clock.cpp:435] Clock of help@172.18.8.37:57116
updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.391826 120659968 sched.cpp:502] Successfully authenticated with
master master@172.18.8.37:57116
I1201 14:52:47.391840 120659968 sched.cpp:824] Sending SUBSCRIBE call to
master@172.18.8.37:57116
I1201 14:52:47.391840 119586816 authenticator.cpp:204] Received SASL
authentication start
I1201 14:52:47.391886 119586816 authenticator.cpp:326] Authentication requires
more steps
I1201 14:52:47.391918 120659968 sched.cpp:857] Will retry registration in
863.906836ms if necessary
I1201 14:52:47.391944 118513664 authenticatee.cpp:259] Received SASL
authentication step
I1201 14:52:47.392076 121196544 master.cpp:2969] Received SUBSCRIBE call for
framework 'default' at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.392094 121196544 master.cpp:2286] Authorizing framework
principal 'test-principal' to receive offers for roles '{ role }'
I1201 14:52:47.392139 121196544 clock.cpp:435] Clock of
local-authorizer(54)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.392231 121733120 authenticator.cpp:232] Received SASL
authentication step
I1201 14:52:47.392251 121733120 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1201 14:52:47.392261 121733120 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1201 14:52:47.392278 121733120 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1201 14:52:47.392292 121733120 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'nfnt.local' server FQDN: 'nfnt.local'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1201 14:52:47.392300 121733120 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.392307 121733120 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1201 14:52:47.392318 121733120 authenticator.cpp:318] Authentication success
I1201 14:52:47.392449 122269696 authenticatee.cpp:299] Authentication success
I1201 14:52:47.392474 119050240 master.cpp:8619] Successfully authenticated
principal 'test-principal' at slave(18)@172.18.8.37:57116
I1201 14:52:47.392523 120123392 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(72)@172.18.8.37:57116
I1201 14:52:47.392602 118513664 master.cpp:3049] Subscribing framework default
with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
I1201 14:52:47.392652 120659968 slave.cpp:1153] Successfully authenticated with
master master@172.18.8.37:57116
I1201 14:52:47.392724 118513664 clock.cpp:435] Clock of
metrics@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.392774 118513664 master.cpp:6950] Updating info for framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.392865 120659968 slave.cpp:1696] Will retry registration in
12.391929ms if necessary
I1201 14:52:47.392976 119050240 hierarchical.cpp:293] Added framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.392999 119050240 hierarchical.cpp:406] Deactivated framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.393084 120123392 sched.cpp:751] Framework registered with
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.393128 120123392 sched.cpp:765] Scheduler::registered took
31032ns
I1201 14:52:47.393184 119050240 hierarchical.cpp:372] Activated framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.393191 118513664 master.cpp:6371] Received re-register agent
message from agent 209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at
slave(18)@172.18.8.37:57116 (172.18.8.37)
I1201 14:52:47.393234 118513664 master.cpp:3878] Authorizing agent with
principal 'test-principal'
I1201 14:52:47.393254 119050240 hierarchical.cpp:1890] No allocations performed
I1201 14:52:47.393266 119050240 hierarchical.cpp:1990] No inverse offers to
send out!
I1201 14:52:47.393278 119050240 hierarchical.cpp:1431] Performed allocation for
0 agents in 45973ns
I1201 14:52:47.393479 121733120 master.cpp:6442] Authorized re-registration of
agent 209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.393527 121733120 master.cpp:6624] Re-registering agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.393579 121733120 clock.cpp:435] Clock of
registrar(36)@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
W1201 14:52:47.393762 119586816 registry_operations.cpp:133] Allowing UNKNOWN
agent to reregister: hostname: "172.18.8.37"
resources {
name: "cpus"
type: SCALAR
scalar {
value: 8
}
role: "*"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 2048
}
role: "*"
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 470537
}
role: "*"
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
role: "*"
}
id {
value: "209387ca-a9c3-4717-9769-a59d9fe927f1-S0"
}
checkpoint: true
port: 57116
I1201 14:52:47.393916 119586816 registrar.cpp:495] Applied 1 operations in
181543ns; attempting to update the registry
I1201 14:52:47.393991 119586816 clock.cpp:435] Clock of
in-memory-storage(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.394055 119586816 clock.cpp:435] Clock of
__latch__(160)@172.18.8.37:57116 updated to 2017-12-01 13:53:05.859857088+00:00
I1201 14:52:47.394348 120123392 registrar.cpp:552] Successfully updated the
registry in 0ns
I1201 14:52:47.394500 119050240 master.cpp:6696] Re-admitted agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.394784 119050240 clock.cpp:435] Clock of
slave-observer(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.394906 119050240 master.cpp:6849] Re-registered agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with cpus:8; mem:2048; disk:470537; ports:[31000-32000]
I1201 14:52:47.395256 122269696 hierarchical.cpp:553] Added agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 (172.18.8.37) with ports:[31000-32000];
cpus(reservations: [(DYNAMIC,role,test-principal)]):8; disk:470537;
mem(reservations: [(DYNAMIC,role,test-principal)]):2048 (allocated: {})
I1201 14:52:47.395566 122269696 hierarchical.cpp:1860] Allocating
ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal)]):8;
disk:470537; mem(reservations: [(DYNAMIC,role,test-principal)]):2048 on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 to role role of framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.395998 121733120 slave.cpp:1343] Re-registered with master
master@172.18.8.37:57116
I1201 14:52:47.396021 121733120 clock.cpp:435] Clock of
task-status-update-manager(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.396041 122269696 hierarchical.cpp:1990] No inverse offers to
send out!
I1201 14:52:47.396050 121733120 clock.cpp:435] Clock of
local-resource-provider-daemon(18)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.859857088+00:00
I1201 14:52:47.396112 122269696 hierarchical.cpp:1431] Performed allocation for
1 agents in 783438ns
I1201 14:52:47.396169 121733120 slave.cpp:1394] Forwarding total resources
ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal)]):8;
disk:470537; mem(reservations: [(DYNAMIC,role,test-principal)]):2048
I1201 14:52:47.396220 121733120 slave.cpp:1411] Forwarding total oversubscribed
resources {}
I1201 14:52:47.396232 121196544 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1201 14:52:47.396296 121733120 slave.cpp:5160] Received ping from
slave-observer(36)@172.18.8.37:57116
I1201 14:52:47.396390 120659968 master.cpp:8419] Sending 1 offers to framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (default) at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.396756 120659968 master.cpp:7036] Received update of agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with total resources ports:[31000-32000]; cpus(reservations:
[(DYNAMIC,role,test-principal)]):8; disk:470537; mem(reservations:
[(DYNAMIC,role,test-principal)]):2048
I1201 14:52:47.396806 120659968 master.cpp:7049] Received update of agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37) with total oversubscribed resources {}
I1201 14:52:47.396842 119050240 sched.cpp:897] Received 1 offers
I1201 14:52:47.396957 119050240 sched.cpp:921] Scheduler::resourceOffers took
81196ns
I1201 14:52:47.397416 120659968 master.cpp:7422] Removing offer
2cadeec8-e39c-486b-bcd9-c24721e36b5a-O0 with resources ports(allocated:
role):[31000-32000]; cpus(allocated: role)(reservations:
[(DYNAMIC,role,test-principal)]):8; disk(allocated: role):470537;
mem(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):2048 on
agent 209387ca-a9c3-4717-9769-a59d9fe927f1-S0 at slave(18)@172.18.8.37:57116
(172.18.8.37)
I1201 14:52:47.397509 119586816 hierarchical.cpp:620] Agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 (172.18.8.37) updated with total
resources ports:[31000-32000]; cpus(reservations:
[(DYNAMIC,role,test-principal)]):8; disk:470537; mem(reservations:
[(DYNAMIC,role,test-principal)]):2048
I1201 14:52:47.397892 120659968 master.cpp:10331] Removing offer
2cadeec8-e39c-486b-bcd9-c24721e36b5a-O0
I1201 14:52:47.398036 122269696 sched.cpp:947] Rescinded offer
2cadeec8-e39c-486b-bcd9-c24721e36b5a-O0
GMOCK WARNING:
Uninteresting mock function call - returning directly.
Function call: offerRescinded(0x7ffee4a13878, @0x7f9f6aa4bfb8
2cadeec8-e39c-486b-bcd9-c24721e36b5a-O0)
NOTE: You can safely ignore the above warning unless this call should not
happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't
mean to enforce the call. See
https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect
for details.
I1201 14:52:47.398121 122269696 sched.cpp:958] Scheduler::offerRescinded took
61218ns
I1201 14:52:47.398532 119586816 hierarchical.cpp:1106] Recovered
ports(allocated: role):[31000-32000]; cpus(allocated: role)(reservations:
[(DYNAMIC,role,test-principal)]):8; disk(allocated: role):470537;
mem(allocated: role)(reservations: [(DYNAMIC,role,test-principal)]):2048
(total: ports:[31000-32000]; cpus(reservations:
[(DYNAMIC,role,test-principal)]):8; disk:470537; mem(reservations:
[(DYNAMIC,role,test-principal)]):2048, allocated: {}) on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 from framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.398988 2720961344 clock.cpp:381] Clock advanced (5ms) to
2017-12-01 13:53:05.864857088+00:00
I1201 14:52:47.399147 122806272 clock.cpp:435] Clock of
hierarchical-allocator(36)@172.18.8.37:57116 updated to 2017-12-01
13:53:05.864857088+00:00
I1201 14:52:47.399618 121196544 hierarchical.cpp:1860] Allocating
ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal)]):8;
disk:470537; mem(reservations: [(DYNAMIC,role,test-principal)]):2048 on agent
209387ca-a9c3-4717-9769-a59d9fe927f1-S0 to role role of framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000
I1201 14:52:47.400048 121196544 clock.cpp:435] Clock of
master@172.18.8.37:57116 updated to 2017-12-01 13:53:05.864857088+00:00
I1201 14:52:47.400128 121196544 hierarchical.cpp:1990] No inverse offers to
send out!
I1201 14:52:47.400143 121196544 hierarchical.cpp:1431] Performed allocation for
1 agents in 774337ns
I1201 14:52:47.400451 120123392 master.cpp:8419] Sending 1 offers to framework
209387ca-a9c3-4717-9769-a59d9fe927f1-0000 (default) at
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116
I1201 14:52:47.400507 120123392 clock.cpp:435] Clock of
scheduler-430784ca-9418-4424-b431-5ce1a96a6fee@172.18.8.37:57116 updated to
2017-12-01 13:53:05.864857088+00:00
I1201 14:52:47.400672 121733120 sched.cpp:897] Received 1 offers
../src/tests/reservation_tests.cpp:938: Failure
Mock function called more times than expected - returning directly.
Function call: resourceOffers(0x7ffee4a13878, @0x700007417160 { 160-byte
object <68-FA A8-22 01-00 00-00 00-00 00-00 00-00 00-00 5F-00 00-00 00-00 00-00
00-00 00-00 00-00 00-00 04-00 00-00 04-00 00-00 C0-E5 C4-6D 9F-7F 00-00 00-00
00-00 00-00 00-00 00-00 00-00 00-00 00-00 ... 50-C6 CB-6A 9F-7F 00-00 70-C6
CB-6A 9F-7F 00-00 E0-C6 CB-6A 9F-7F 00-00 40-DC C3-6D 9F-7F 00-00 B0-DC C3-6D
9F-7F 00-00 00-00 00-00 00-00 00-00 50-B4 C4-6D 9F-7F 00-00 00-00 00-00 00-00
00-00> })
Expected: to be called once
Actual: called twice - over-saturated and active
*** Aborted at 1512136367 (unix time) try "date -d @1512136367" if you are
using GNU date ***
PC: @ 0x10d94677a testing::UnitTest::AddTestPartResult()
*** SIGSEGV (@0x0) received by PID 53782 (TID 0x700007418000) stack trace: ***
@ 0x7fff68f19f5a _sigtramp
@ 0x2c0 (unknown)
@ 0x10d945f3b testing::internal::AssertHelper::operator=()
@ 0x10d9c187f
testing::internal::GoogleTestFailureReporter::ReportFailure()
@ 0x10b344315 testing::internal::Expect()
@ 0x10d9bc9b5
testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
@ 0x10b59d6eb
_ZN7testing8internal18FunctionMockerBaseIFvPN5mesos15SchedulerDriverERKNSt3__16vectorINS2_5OfferENS5_9allocatorIS7_EEEEEE10InvokeWithERKNS5_5tupleIJS4_SC_EEE
@ 0x10b59d698 testing::internal::FunctionMocker<>::Invoke()
@ 0x10b544c8d mesos::internal::tests::MockScheduler::resourceOffers()
@ 0x117f1a432 mesos::internal::SchedulerProcess::resourceOffers()
@ 0x117f2dad5
_ZN15ProtobufProcessIN5mesos8internal16SchedulerProcessEE8handlerNINS1_21ResourceOffersMessageEJRKN6google8protobuf16RepeatedPtrFieldINS0_5OfferEEERKNS8_INSt3__112basic_stringIcNSD_11char_traitsIcEENSD_9allocatorIcEEEEEEEJRKNSD_6vectorIS9_NSH_IS9_EEEERKNSN_ISJ_NSH_ISJ_EEEEEEEvPS2_MS2_FvRKN7process4UPIDEDpT1_ES10_RKSJ_DpMT_KFT0_vE
@ 0x117f2fe32
_ZNSt3__128__invoke_void_return_wrapperIvE6__callIJRNS_6__bindIRFvPN5mesos8internal16SchedulerProcessEMS6_FvRKN7process4UPIDERKNS_6vectorINS4_5OfferENS_9allocatorISD_EEEERKNSC_INS_12basic_stringIcNS_11char_traitsIcEENSE_IcEEEENSE_ISN_EEEEESB_RKSN_MNS5_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldISD_EEvEMSW_KFRKNSZ_ISN_EEvEEJRS7_RST_RKNS_12placeholders4__phILi1EEERKNS1F_ILi2EEERS14_RS19_EEESB_SV_EEEvDpOT_
@ 0x117f2f79c
_ZNSt3__110__function6__funcINS_6__bindIRFvPN5mesos8internal16SchedulerProcessEMS5_FvRKN7process4UPIDERKNS_6vectorINS3_5OfferENS_9allocatorISC_EEEERKNSB_INS_12basic_stringIcNS_11char_traitsIcEENSD_IcEEEENSD_ISM_EEEEESA_RKSM_MNS4_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldISC_EEvEMSV_KFRKNSY_ISM_EEvEEJRS6_RSS_RKNS_12placeholders4__phILi1EEERKNS1E_ILi2EEERS13_RS18_EEENSD_IS1N_EEFvSA_SU_EEclESA_SU_
@ 0x10b669322 std::__1::function<>::operator()()
@ 0x117f0dff2 ProtobufProcess<>::visit()
@ 0x112a19aae process::MessageEvent::visit()
@ 0x1150a7e71 process::ProcessBase::serve()
@ 0x11296d59b process::ProcessManager::resume()
@ 0x112ac270b
process::ProcessManager::init_threads()::$_1::operator()()
@ 0x112ac2290
_ZNSt3__114__thread_proxyINS_5tupleIJNS_10unique_ptrINS_15__thread_structENS_14default_deleteIS3_EEEEZN7process14ProcessManager12init_threadsEvE3$_1EEEEEPvSB_
@ 0x7fff68f236c1 _pthread_body
@ 0x7fff68f2356d _pthread_start
@ 0x7fff68f22c5d thread_start
Segmentation fault: 11
{noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
