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/12/01 15:22:00 UTC
[jira] [Updated] (MESOS-8289) ReservationTest.MasterFailover is
flaky when run with `RESOURCE_PROVIDER` capability
[ https://issues.apache.org/jira/browse/MESOS-8289?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexander Rukletsov updated MESOS-8289:
---------------------------------------
Labels: flaky flaky-test mesosphere (was: flaky mesosphere)
> 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
> Labels: flaky, flaky-test, mesosphere
> 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)