[
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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]:57116 updated to
> 2017-12-01 13:53:04.844857088+00:00
> I1201 14:52:47.366179 2720961344 clock.cpp:435] Clock of
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]:57116
> I1201 14:52:47.367899 119050240 sched.cpp:824] Sending SUBSCRIBE call to
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:57116
> I1201 14:52:47.369753 119050240 clock.cpp:435] Clock of
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:57116
> I1201 14:52:47.379434 2720961344 process.cpp:2730] Dropping event for process
> [email protected]:57116
> I1201 14:52:47.379631 2720961344 clock.cpp:435] Clock of
> [email protected]:57116 updated to 2017-12-01 13:53:04.849857088+00:00
> I1201 14:52:47.379984 2720961344 clock.cpp:435] Clock of
> [email protected]: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
> [email protected]: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
> [email protected]:57116 updated to 2017-12-01 13:53:05.121836864+00:00
> I1201 14:52:47.389757 122806272 clock.cpp:435] Clock of
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:57116
> I1201 14:52:47.390486 120659968 master.cpp:8589] Authenticating
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]:57116
> I1201 14:52:47.391840 120659968 sched.cpp:824] Sending SUBSCRIBE call to
> [email protected]: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
> [email protected]: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 [email protected]:57116
> I1201 14:52:47.392724 118513664 clock.cpp:435] Clock of
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:57116
> I1201 14:52:47.400507 120123392 clock.cpp:435] Clock of
> [email protected]: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)
