You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2017/06/27 18:16:00 UTC
[jira] [Updated] (MESOS-7725)
PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval test is flaky
[ https://issues.apache.org/jira/browse/MESOS-7725?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone updated MESOS-7725:
------------------------------
Description:
Observed this on ASF CI.
{code}
[ RUN ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval
I0627 15:20:33.687146 30773 cluster.cpp:162] Creating default 'local' authorizer
I0627 15:20:33.691745 30795 master.cpp:438] Master d8d232e5-1689-4780-b232-c91e5c3277b1 (0b1049f05548) started on 172.17.0.2:44357
I0627 15:20:33.691800 30795 master.cpp:440] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/Wg4Ouh/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="role1" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/Wg4Ouh/master" --zk_session_timeout="10secs"
I0627 15:20:33.692142 30795 master.cpp:490] Master only allowing authenticated frameworks to register
I0627 15:20:33.692150 30795 master.cpp:504] Master only allowing authenticated agents to register
I0627 15:20:33.692154 30795 master.cpp:517] Master only allowing authenticated HTTP frameworks to register
I0627 15:20:33.692160 30795 credentials.hpp:37] Loading credentials for authentication from '/tmp/Wg4Ouh/credentials'
I0627 15:20:33.692463 30795 master.cpp:562] Using default 'crammd5' authenticator
I0627 15:20:33.692612 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0627 15:20:33.692831 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0627 15:20:33.692942 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0627 15:20:33.693061 30795 master.cpp:642] Authorization enabled
W0627 15:20:33.693076 30795 master.cpp:705] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0627 15:20:33.693354 30780 hierarchical.cpp:169] Initialized hierarchical allocator process
I0627 15:20:33.693359 30782 whitelist_watcher.cpp:77] No whitelist given
I0627 15:20:33.695943 30795 master.cpp:2161] Elected as the leading master!
I0627 15:20:33.695960 30795 master.cpp:1700] Recovering from registrar
I0627 15:20:33.696193 30795 registrar.cpp:345] Recovering registrar
I0627 15:20:33.697032 30795 registrar.cpp:389] Successfully fetched the registry (0B) in 811008ns
I0627 15:20:33.697147 30795 registrar.cpp:493] Applied 1 operations in 40183ns; attempting to update the registry
I0627 15:20:33.697922 30792 registrar.cpp:550] Successfully updated the registry in 709120ns
I0627 15:20:33.698020 30792 registrar.cpp:422] Successfully recovered registrar
I0627 15:20:33.698490 30789 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0627 15:20:33.698511 30784 hierarchical.cpp:207] Skipping recovery of hierarchical allocator: nothing to recover
I0627 15:20:33.707849 30773 containerizer.cpp:230] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
W0627 15:20:33.708729 30773 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0627 15:20:33.708909 30773 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0627 15:20:33.708955 30773 provisioner.cpp:255] Using default backend 'copy'
I0627 15:20:33.711526 30773 cluster.cpp:448] Creating default 'local' authorizer
I0627 15:20:33.714450 30776 slave.cpp:249] Mesos agent started on (451)@172.17.0.2:44357
I0627 15:20:33.714649 30776 slave.cpp:250] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/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="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:4" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf"
I0627 15:20:33.715536 30776 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/credential'
I0627 15:20:33.715909 30776 slave.cpp:282] Agent using credential for: test-principal
I0627 15:20:33.716008 30776 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credentials'
I0627 15:20:33.716431 30776 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0627 15:20:33.716806 30776 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0627 15:20:33.717967 30776 slave.cpp:553] Agent resources: [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0627 15:20:33.718209 30776 slave.cpp:561] Agent attributes: [ ]
I0627 15:20:33.718225 30776 slave.cpp:566] Agent hostname: 0b1049f05548
I0627 15:20:33.718375 30783 status_update_manager.cpp:177] Pausing sending status updates
I0627 15:20:33.720067 30795 state.cpp:64] Recovering state from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta'
I0627 15:20:33.720432 30778 status_update_manager.cpp:203] Recovering status update manager
I0627 15:20:33.720608 30795 containerizer.cpp:582] Recovering containerizer
I0627 15:20:33.722419 30790 provisioner.cpp:416] Provisioner recovery complete
I0627 15:20:33.722766 30786 slave.cpp:6168] Finished recovery
I0627 15:20:33.723409 30786 slave.cpp:6350] Querying resource estimator for oversubscribable resources
I0627 15:20:33.724009 30784 slave.cpp:946] New master detected at master@172.17.0.2:44357
I0627 15:20:33.724221 30784 slave.cpp:981] Detecting new master
I0627 15:20:33.724370 30784 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
I0627 15:20:33.725513 30784 slave.cpp:1008] Authenticating with master master@172.17.0.2:44357
I0627 15:20:33.725639 30784 slave.cpp:1019] Using default CRAM-MD5 authenticatee
I0627 15:20:33.725975 30784 authenticatee.cpp:121] Creating new client SASL connection
I0627 15:20:33.726358 30784 master.cpp:7640] Authenticating slave(451)@172.17.0.2:44357
I0627 15:20:33.726567 30784 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(938)@172.17.0.2:44357
I0627 15:20:33.726917 30784 authenticator.cpp:98] Creating new server SASL connection
I0627 15:20:33.727162 30784 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0627 15:20:33.727192 30784 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0627 15:20:33.727285 30784 authenticator.cpp:204] Received SASL authentication start
I0627 15:20:33.727344 30784 authenticator.cpp:326] Authentication requires more steps
I0627 15:20:33.727429 30784 authenticatee.cpp:259] Received SASL authentication step
I0627 15:20:33.727546 30781 status_update_manager.cpp:177] Pausing sending status updates
I0627 15:20:33.727591 30784 authenticator.cpp:232] Received SASL authentication step
I0627 15:20:33.727624 30784 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0627 15:20:33.727640 30784 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0627 15:20:33.727690 30784 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0627 15:20:33.727715 30784 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0627 15:20:33.727726 30784 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.727737 30784 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.727757 30784 authenticator.cpp:318] Authentication success
I0627 15:20:33.727963 30784 authenticatee.cpp:299] Authentication success
I0627 15:20:33.728052 30784 master.cpp:7670] Successfully authenticated principal 'test-principal' at slave(451)@172.17.0.2:44357
I0627 15:20:33.728145 30784 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(938)@172.17.0.2:44357
I0627 15:20:33.728500 30784 slave.cpp:1103] Successfully authenticated with master master@172.17.0.2:44357
I0627 15:20:33.728786 30784 slave.cpp:1545] Will retry registration in 1.216522ms if necessary
I0627 15:20:33.729225 30784 master.cpp:5602] Received register agent message from slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.729265 30784 master.cpp:3742] Authorizing agent with principal 'test-principal'
I0627 15:20:33.729861 30784 master.cpp:5662] Authorized registration of agent at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.729984 30784 master.cpp:5741] Registering agent at slave(451)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3277b1-S0
I0627 15:20:33.730517 30784 registrar.cpp:493] Applied 1 operations in 89878ns; attempting to update the registry
I0627 15:20:33.731552 30784 registrar.cpp:550] Successfully updated the registry in 956928ns
I0627 15:20:33.731950 30784 slave.cpp:1545] Will retry registration in 4.853741ms if necessary
I0627 15:20:33.732209 30784 master.cpp:5788] Admitted agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.732918 30784 master.cpp:5819] Registered agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0627 15:20:33.733402 30784 master.cpp:5602] Received register agent message from slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.733438 30784 master.cpp:3742] Authorizing agent with principal 'test-principal'
I0627 15:20:33.734184 30784 hierarchical.cpp:587] Added agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 (0b1049f05548) with cpus:4; mem:95614; disk:367489; ports:[31000-32000] (allocated: {})
I0627 15:20:33.734509 30784 hierarchical.cpp:1938] No allocations performed
I0627 15:20:33.734563 30784 hierarchical.cpp:1493] Performed allocation for 1 agents in 203705ns
I0627 15:20:33.734794 30784 slave.cpp:1149] Registered with master master@172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S0
I0627 15:20:33.735222 30784 slave.cpp:1169] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta/slaves/d8d232e5-1689-4780-b232-c91e5c3277b1-S0/slave.info'
I0627 15:20:33.735703 30784 slave.cpp:1207] Forwarding total oversubscribed resources {}
I0627 15:20:33.735824 30784 slave.cpp:4866] Received ping from slave-observer(449)@172.17.0.2:44357
I0627 15:20:33.736479 30784 status_update_manager.cpp:184] Resuming sending status updates
I0627 15:20:33.736613 30784 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
I0627 15:20:33.736809 30784 master.cpp:5662] Authorized registration of agent at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.736912 30784 master.cpp:5719] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) already registered, resending acknowledgement
W0627 15:20:33.737525 30777 slave.cpp:1193] Already registered with master master@172.17.0.2:44357
I0627 15:20:33.737548 30777 slave.cpp:1207] Forwarding total oversubscribed resources {}
I0627 15:20:33.737752 30775 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
I0627 15:20:33.744215 30775 hierarchical.cpp:1938] No allocations performed
I0627 15:20:33.744280 30775 hierarchical.cpp:1493] Performed allocation for 1 agents in 249949ns
I0627 15:20:33.745524 30773 containerizer.cpp:230] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
W0627 15:20:33.746350 30773 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0627 15:20:33.746516 30773 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0627 15:20:33.746562 30773 provisioner.cpp:255] Using default backend 'copy'
I0627 15:20:33.749130 30773 cluster.cpp:448] Creating default 'local' authorizer
I0627 15:20:33.751713 30774 slave.cpp:249] Mesos agent started on (452)@172.17.0.2:44357
I0627 15:20:33.751760 30774 slave.cpp:250] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/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="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:3" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8"
I0627 15:20:33.752180 30774 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/credential'
I0627 15:20:33.752401 30774 slave.cpp:282] Agent using credential for: test-principal
I0627 15:20:33.752419 30774 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credentials'
I0627 15:20:33.752648 30774 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0627 15:20:33.752821 30774 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0627 15:20:33.753873 30774 slave.cpp:553] Agent resources: [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0627 15:20:33.754041 30774 slave.cpp:561] Agent attributes: [ ]
I0627 15:20:33.754051 30774 slave.cpp:566] Agent hostname: 0b1049f05548
I0627 15:20:33.754200 30788 status_update_manager.cpp:177] Pausing sending status updates
I0627 15:20:33.755672 30792 state.cpp:64] Recovering state from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta'
I0627 15:20:33.755934 30790 status_update_manager.cpp:203] Recovering status update manager
I0627 15:20:33.756114 30789 containerizer.cpp:582] Recovering containerizer
I0627 15:20:33.756492 30778 process.cpp:3779] Handling HTTP event for process 'master' with path: '/master/reserve'
I0627 15:20:33.757879 30783 provisioner.cpp:416] Provisioner recovery complete
I0627 15:20:33.758180 30784 slave.cpp:6168] Finished recovery
I0627 15:20:33.758538 30780 http.cpp:1114] HTTP POST for /master/reserve from 172.17.0.2:44414
I0627 15:20:33.758766 30784 slave.cpp:6350] Querying resource estimator for oversubscribable resources
I0627 15:20:33.758973 30795 status_update_manager.cpp:177] Pausing sending status updates
I0627 15:20:33.758972 30784 slave.cpp:946] New master detected at master@172.17.0.2:44357
I0627 15:20:33.759085 30784 slave.cpp:981] Detecting new master
I0627 15:20:33.759176 30784 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
I0627 15:20:33.759441 30780 master.cpp:3527] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":4.0},"type":"SCALAR"}]'
I0627 15:20:33.761719 30779 master.cpp:8908] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 to agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.762620 30794 slave.cpp:3426] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role1,test-principal)]):4
I0627 15:20:33.763795 30775 slave.cpp:1008] Authenticating with master master@172.17.0.2:44357
I0627 15:20:33.763928 30775 slave.cpp:1019] Using default CRAM-MD5 authenticatee
I0627 15:20:33.764186 30795 authenticatee.cpp:121] Creating new client SASL connection
I0627 15:20:33.764468 30796 master.cpp:7640] Authenticating slave(452)@172.17.0.2:44357
I0627 15:20:33.764649 30785 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(939)@172.17.0.2:44357
I0627 15:20:33.764925 30795 authenticator.cpp:98] Creating new server SASL connection
I0627 15:20:33.765175 30777 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0627 15:20:33.765203 30777 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0627 15:20:33.765386 30785 authenticator.cpp:204] Received SASL authentication start
I0627 15:20:33.765439 30785 authenticator.cpp:326] Authentication requires more steps
I0627 15:20:33.765538 30784 authenticatee.cpp:259] Received SASL authentication step
I0627 15:20:33.765709 30789 authenticator.cpp:232] Received SASL authentication step
I0627 15:20:33.765758 30789 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0627 15:20:33.765774 30789 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0627 15:20:33.765825 30789 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0627 15:20:33.765854 30789 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0627 15:20:33.765867 30789 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.765877 30789 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.765902 30789 authenticator.cpp:318] Authentication success
I0627 15:20:33.766007 30773 sched.cpp:232] Version: 1.4.0
I0627 15:20:33.766126 30790 authenticatee.cpp:299] Authentication success
I0627 15:20:33.766155 30788 master.cpp:7670] Successfully authenticated principal 'test-principal' at slave(452)@172.17.0.2:44357
I0627 15:20:33.766187 30789 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(939)@172.17.0.2:44357
I0627 15:20:33.766543 30776 slave.cpp:1103] Successfully authenticated with master master@172.17.0.2:44357
I0627 15:20:33.766687 30793 sched.cpp:336] New master detected at master@172.17.0.2:44357
I0627 15:20:33.766753 30793 sched.cpp:407] Authenticating with master master@172.17.0.2:44357
I0627 15:20:33.766767 30793 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0627 15:20:33.766770 30776 slave.cpp:1545] Will retry registration in 2.625286ms if necessary
I0627 15:20:33.766901 30789 master.cpp:5602] Received register agent message from slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.766932 30789 master.cpp:3742] Authorizing agent with principal 'test-principal'
I0627 15:20:33.766964 30797 authenticatee.cpp:121] Creating new client SASL connection
I0627 15:20:33.767232 30789 master.cpp:7640] Authenticating scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.767307 30776 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(940)@172.17.0.2:44357
I0627 15:20:33.767468 30774 master.cpp:5662] Authorized registration of agent at slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.767489 30797 authenticator.cpp:98] Creating new server SASL connection
I0627 15:20:33.767608 30774 master.cpp:5741] Registering agent at slave(452)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3277b1-S1
I0627 15:20:33.767666 30778 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0627 15:20:33.767691 30778 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0627 15:20:33.767819 30797 authenticator.cpp:204] Received SASL authentication start
I0627 15:20:33.767864 30797 authenticator.cpp:326] Authentication requires more steps
I0627 15:20:33.767958 30786 authenticatee.cpp:259] Received SASL authentication step
I0627 15:20:33.767989 30781 registrar.cpp:493] Applied 1 operations in 89291ns; attempting to update the registry
I0627 15:20:33.768164 30788 authenticator.cpp:232] Received SASL authentication step
I0627 15:20:33.768187 30788 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0627 15:20:33.768198 30788 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0627 15:20:33.768239 30788 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0627 15:20:33.768260 30788 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0627 15:20:33.768267 30788 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.768272 30788 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0627 15:20:33.768285 30788 authenticator.cpp:318] Authentication success
I0627 15:20:33.768394 30792 authenticatee.cpp:299] Authentication success
I0627 15:20:33.768615 30777 master.cpp:7670] Successfully authenticated principal 'test-principal' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.768641 30790 sched.cpp:513] Successfully authenticated with master master@172.17.0.2:44357
I0627 15:20:33.768661 30790 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.2:44357
I0627 15:20:33.768661 30776 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(940)@172.17.0.2:44357
I0627 15:20:33.768782 30781 registrar.cpp:550] Successfully updated the registry in 722176ns
I0627 15:20:33.768887 30790 sched.cpp:869] Will retry registration in 424.478509ms if necessary
I0627 15:20:33.769176 30785 master.cpp:2853] Received SUBSCRIBE call for framework 'default' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.769222 30785 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }'
I0627 15:20:33.770375 30796 slave.cpp:1545] Will retry registration in 37.054423ms if necessary
I0627 15:20:33.770567 30785 master.cpp:5788] Admitted agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.771241 30784 slave.cpp:4866] Received ping from slave-observer(450)@172.17.0.2:44357
I0627 15:20:33.771467 30787 slave.cpp:1149] Registered with master master@172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S1
I0627 15:20:33.771585 30789 status_update_manager.cpp:184] Resuming sending status updates
I0627 15:20:33.771392 30785 master.cpp:5819] Registered agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0627 15:20:33.771682 30777 hierarchical.cpp:587] Added agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 (0b1049f05548) with cpus:3; mem:95614; disk:367489; ports:[31000-32000] (allocated: {})
I0627 15:20:33.771832 30787 slave.cpp:1169] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta/slaves/d8d232e5-1689-4780-b232-c91e5c3277b1-S1/slave.info'
I0627 15:20:33.771932 30777 hierarchical.cpp:1938] No allocations performed
I0627 15:20:33.771953 30785 master.cpp:5602] Received register agent message from slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.771975 30777 hierarchical.cpp:1493] Performed allocation for 1 agents in 164163ns
I0627 15:20:33.771996 30785 master.cpp:3742] Authorizing agent with principal 'test-principal'
I0627 15:20:33.772150 30787 slave.cpp:1207] Forwarding total oversubscribed resources {}
I0627 15:20:33.772339 30785 master.cpp:2933] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
I0627 15:20:33.773007 30785 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
I0627 15:20:33.773047 30794 sched.cpp:759] Framework registered with d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.773095 30794 sched.cpp:773] Scheduler::registered took 31019ns
I0627 15:20:33.773164 30785 master.cpp:5662] Authorized registration of agent at slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.773227 30776 hierarchical.cpp:301] Added framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.773247 30785 master.cpp:5719] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) already registered, resending acknowledgement
W0627 15:20:33.773438 30783 slave.cpp:1193] Already registered with master master@172.17.0.2:44357
I0627 15:20:33.773470 30783 slave.cpp:1207] Forwarding total oversubscribed resources {}
I0627 15:20:33.773676 30781 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
I0627 15:20:33.774871 30776 hierarchical.cpp:2028] No inverse offers to send out!
I0627 15:20:33.774912 30776 hierarchical.cpp:1493] Performed allocation for 2 agents in 1.518176ms
I0627 15:20:33.776294 30783 master.cpp:7470] Sending 2 offers to framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.776959 30776 sched.cpp:933] Scheduler::resourceOffers took 133421ns
/mesos/src/tests/persistent_volume_endpoints_tests.cpp:1859: Failure
Value of: offeredSlaveId == slaveId1 || offeredSlaveId == slaveId2
Actual: false
Expected: true
I0627 15:20:33.778265 30791 master.cpp:1430] Framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 disconnected
I0627 15:20:33.778303 30791 master.cpp:3203] Deactivating framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.779554 30787 hierarchical.cpp:410] Deactivated framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.779958 30791 master.cpp:3180] Disconnecting framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.780009 30791 master.cpp:1445] Giving framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 0ns to failover
I0627 15:20:33.780483 30787 hierarchical.cpp:1177] Recovered ports(allocated: role1):[31000-32000]; mem(allocated: role1):95614; disk(allocated: role1):367489; cpus(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):4 (total: ports:[31000-32000]; mem:95614; disk:367489; cpus(reservations: [(DYNAMIC,role1,test-principal)]):4, allocated: {}) on agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.781185 30787 hierarchical.cpp:1177] Recovered cpus(allocated: role1):3; mem(allocated: role1):95614; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000] (total: cpus:3; mem:95614; disk:367489; ports:[31000-32000], allocated: {}) on agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.781599 30789 master.cpp:7306] Framework failover timeout, removing framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.781625 30789 master.cpp:8163] Removing framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
I0627 15:20:33.781790 30787 slave.cpp:3136] Asked to shut down framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357
I0627 15:20:33.781803 30791 slave.cpp:3136] Asked to shut down framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357
I0627 15:20:33.781817 30787 slave.cpp:3151] Cannot shut down unknown framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.781831 30791 slave.cpp:3151] Cannot shut down unknown framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.782289 30780 hierarchical.cpp:353] Removed framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
I0627 15:20:33.788432 30787 slave.cpp:818] Agent terminating
I0627 15:20:33.788750 30796 master.cpp:1316] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) disconnected
I0627 15:20:33.788781 30796 master.cpp:3240] Disconnecting agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.788859 30796 master.cpp:3259] Deactivating agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.788995 30777 hierarchical.cpp:715] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 deactivated
I0627 15:20:33.796249 30779 hierarchical.cpp:1938] No allocations performed
I0627 15:20:33.796330 30779 hierarchical.cpp:1493] Performed allocation for 2 agents in 319501ns
I0627 15:20:33.798933 30796 slave.cpp:818] Agent terminating
I0627 15:20:33.799327 30795 master.cpp:1316] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) disconnected
I0627 15:20:33.799360 30795 master.cpp:3240] Disconnecting agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.799438 30795 master.cpp:3259] Deactivating agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
I0627 15:20:33.799567 30787 hierarchical.cpp:715] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 deactivated
I0627 15:20:33.804204 30779 master.cpp:1158] Master terminating
I0627 15:20:33.810475 30780 hierarchical.cpp:620] Removed agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1
I0627 15:20:33.811208 30780 hierarchical.cpp:620] Removed agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0
/mesos/3rdparty/libprocess/include/process/gmock.hpp:441: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <B8-F3 06-40 86-2B 00-00>, 1, 1)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval (138 ms)
{code}
[~neilconway] Can you take a look at this? This has been terribly flaky on ASF CI.
was:
Observed this on ASF CI.
Will paste the log once I find a failing build whose logs are not rotated out.
> PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval test is flaky
> ------------------------------------------------------------------
>
> Key: MESOS-7725
> URL: https://issues.apache.org/jira/browse/MESOS-7725
> Project: Mesos
> Issue Type: Bug
> Reporter: Vinod Kone
> Assignee: Neil Conway
> Labels: flaky-test, mesosphere-oncall
>
> Observed this on ASF CI.
> {code}
> [ RUN ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval
> I0627 15:20:33.687146 30773 cluster.cpp:162] Creating default 'local' authorizer
> I0627 15:20:33.691745 30795 master.cpp:438] Master d8d232e5-1689-4780-b232-c91e5c3277b1 (0b1049f05548) started on 172.17.0.2:44357
> I0627 15:20:33.691800 30795 master.cpp:440] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/Wg4Ouh/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="role1" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/Wg4Ouh/master" --zk_session_timeout="10secs"
> I0627 15:20:33.692142 30795 master.cpp:490] Master only allowing authenticated frameworks to register
> I0627 15:20:33.692150 30795 master.cpp:504] Master only allowing authenticated agents to register
> I0627 15:20:33.692154 30795 master.cpp:517] Master only allowing authenticated HTTP frameworks to register
> I0627 15:20:33.692160 30795 credentials.hpp:37] Loading credentials for authentication from '/tmp/Wg4Ouh/credentials'
> I0627 15:20:33.692463 30795 master.cpp:562] Using default 'crammd5' authenticator
> I0627 15:20:33.692612 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> I0627 15:20:33.692831 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> I0627 15:20:33.692942 30795 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> I0627 15:20:33.693061 30795 master.cpp:642] Authorization enabled
> W0627 15:20:33.693076 30795 master.cpp:705] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
> I0627 15:20:33.693354 30780 hierarchical.cpp:169] Initialized hierarchical allocator process
> I0627 15:20:33.693359 30782 whitelist_watcher.cpp:77] No whitelist given
> I0627 15:20:33.695943 30795 master.cpp:2161] Elected as the leading master!
> I0627 15:20:33.695960 30795 master.cpp:1700] Recovering from registrar
> I0627 15:20:33.696193 30795 registrar.cpp:345] Recovering registrar
> I0627 15:20:33.697032 30795 registrar.cpp:389] Successfully fetched the registry (0B) in 811008ns
> I0627 15:20:33.697147 30795 registrar.cpp:493] Applied 1 operations in 40183ns; attempting to update the registry
> I0627 15:20:33.697922 30792 registrar.cpp:550] Successfully updated the registry in 709120ns
> I0627 15:20:33.698020 30792 registrar.cpp:422] Successfully recovered registrar
> I0627 15:20:33.698490 30789 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
> I0627 15:20:33.698511 30784 hierarchical.cpp:207] Skipping recovery of hierarchical allocator: nothing to recover
> I0627 15:20:33.707849 30773 containerizer.cpp:230] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
> W0627 15:20:33.708729 30773 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
> W0627 15:20:33.708909 30773 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
> I0627 15:20:33.708955 30773 provisioner.cpp:255] Using default backend 'copy'
> I0627 15:20:33.711526 30773 cluster.cpp:448] Creating default 'local' authorizer
> I0627 15:20:33.714450 30776 slave.cpp:249] Mesos agent started on (451)@172.17.0.2:44357
> I0627 15:20:33.714649 30776 slave.cpp:250] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/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="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:4" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf"
> I0627 15:20:33.715536 30776 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/credential'
> I0627 15:20:33.715909 30776 slave.cpp:282] Agent using credential for: test-principal
> I0627 15:20:33.716008 30776 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credentials'
> I0627 15:20:33.716431 30776 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> I0627 15:20:33.716806 30776 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0627 15:20:33.717967 30776 slave.cpp:553] Agent resources: [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 15:20:33.718209 30776 slave.cpp:561] Agent attributes: [ ]
> I0627 15:20:33.718225 30776 slave.cpp:566] Agent hostname: 0b1049f05548
> I0627 15:20:33.718375 30783 status_update_manager.cpp:177] Pausing sending status updates
> I0627 15:20:33.720067 30795 state.cpp:64] Recovering state from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta'
> I0627 15:20:33.720432 30778 status_update_manager.cpp:203] Recovering status update manager
> I0627 15:20:33.720608 30795 containerizer.cpp:582] Recovering containerizer
> I0627 15:20:33.722419 30790 provisioner.cpp:416] Provisioner recovery complete
> I0627 15:20:33.722766 30786 slave.cpp:6168] Finished recovery
> I0627 15:20:33.723409 30786 slave.cpp:6350] Querying resource estimator for oversubscribable resources
> I0627 15:20:33.724009 30784 slave.cpp:946] New master detected at master@172.17.0.2:44357
> I0627 15:20:33.724221 30784 slave.cpp:981] Detecting new master
> I0627 15:20:33.724370 30784 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
> I0627 15:20:33.725513 30784 slave.cpp:1008] Authenticating with master master@172.17.0.2:44357
> I0627 15:20:33.725639 30784 slave.cpp:1019] Using default CRAM-MD5 authenticatee
> I0627 15:20:33.725975 30784 authenticatee.cpp:121] Creating new client SASL connection
> I0627 15:20:33.726358 30784 master.cpp:7640] Authenticating slave(451)@172.17.0.2:44357
> I0627 15:20:33.726567 30784 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(938)@172.17.0.2:44357
> I0627 15:20:33.726917 30784 authenticator.cpp:98] Creating new server SASL connection
> I0627 15:20:33.727162 30784 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0627 15:20:33.727192 30784 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0627 15:20:33.727285 30784 authenticator.cpp:204] Received SASL authentication start
> I0627 15:20:33.727344 30784 authenticator.cpp:326] Authentication requires more steps
> I0627 15:20:33.727429 30784 authenticatee.cpp:259] Received SASL authentication step
> I0627 15:20:33.727546 30781 status_update_manager.cpp:177] Pausing sending status updates
> I0627 15:20:33.727591 30784 authenticator.cpp:232] Received SASL authentication step
> I0627 15:20:33.727624 30784 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0627 15:20:33.727640 30784 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0627 15:20:33.727690 30784 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0627 15:20:33.727715 30784 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0627 15:20:33.727726 30784 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.727737 30784 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.727757 30784 authenticator.cpp:318] Authentication success
> I0627 15:20:33.727963 30784 authenticatee.cpp:299] Authentication success
> I0627 15:20:33.728052 30784 master.cpp:7670] Successfully authenticated principal 'test-principal' at slave(451)@172.17.0.2:44357
> I0627 15:20:33.728145 30784 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(938)@172.17.0.2:44357
> I0627 15:20:33.728500 30784 slave.cpp:1103] Successfully authenticated with master master@172.17.0.2:44357
> I0627 15:20:33.728786 30784 slave.cpp:1545] Will retry registration in 1.216522ms if necessary
> I0627 15:20:33.729225 30784 master.cpp:5602] Received register agent message from slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.729265 30784 master.cpp:3742] Authorizing agent with principal 'test-principal'
> I0627 15:20:33.729861 30784 master.cpp:5662] Authorized registration of agent at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.729984 30784 master.cpp:5741] Registering agent at slave(451)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3277b1-S0
> I0627 15:20:33.730517 30784 registrar.cpp:493] Applied 1 operations in 89878ns; attempting to update the registry
> I0627 15:20:33.731552 30784 registrar.cpp:550] Successfully updated the registry in 956928ns
> I0627 15:20:33.731950 30784 slave.cpp:1545] Will retry registration in 4.853741ms if necessary
> I0627 15:20:33.732209 30784 master.cpp:5788] Admitted agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.732918 30784 master.cpp:5819] Registered agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 15:20:33.733402 30784 master.cpp:5602] Received register agent message from slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.733438 30784 master.cpp:3742] Authorizing agent with principal 'test-principal'
> I0627 15:20:33.734184 30784 hierarchical.cpp:587] Added agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 (0b1049f05548) with cpus:4; mem:95614; disk:367489; ports:[31000-32000] (allocated: {})
> I0627 15:20:33.734509 30784 hierarchical.cpp:1938] No allocations performed
> I0627 15:20:33.734563 30784 hierarchical.cpp:1493] Performed allocation for 1 agents in 203705ns
> I0627 15:20:33.734794 30784 slave.cpp:1149] Registered with master master@172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S0
> I0627 15:20:33.735222 30784 slave.cpp:1169] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta/slaves/d8d232e5-1689-4780-b232-c91e5c3277b1-S0/slave.info'
> I0627 15:20:33.735703 30784 slave.cpp:1207] Forwarding total oversubscribed resources {}
> I0627 15:20:33.735824 30784 slave.cpp:4866] Received ping from slave-observer(449)@172.17.0.2:44357
> I0627 15:20:33.736479 30784 status_update_manager.cpp:184] Resuming sending status updates
> I0627 15:20:33.736613 30784 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
> I0627 15:20:33.736809 30784 master.cpp:5662] Authorized registration of agent at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.736912 30784 master.cpp:5719] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) already registered, resending acknowledgement
> W0627 15:20:33.737525 30777 slave.cpp:1193] Already registered with master master@172.17.0.2:44357
> I0627 15:20:33.737548 30777 slave.cpp:1207] Forwarding total oversubscribed resources {}
> I0627 15:20:33.737752 30775 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
> I0627 15:20:33.744215 30775 hierarchical.cpp:1938] No allocations performed
> I0627 15:20:33.744280 30775 hierarchical.cpp:1493] Performed allocation for 1 agents in 249949ns
> I0627 15:20:33.745524 30773 containerizer.cpp:230] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
> W0627 15:20:33.746350 30773 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
> W0627 15:20:33.746516 30773 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
> I0627 15:20:33.746562 30773 provisioner.cpp:255] Using default backend 'copy'
> I0627 15:20:33.749130 30773 cluster.cpp:448] Creating default 'local' authorizer
> I0627 15:20:33.751713 30774 slave.cpp:249] Mesos agent started on (452)@172.17.0.2:44357
> I0627 15:20:33.751760 30774 slave.cpp:250] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/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="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:3" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8"
> I0627 15:20:33.752180 30774 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/credential'
> I0627 15:20:33.752401 30774 slave.cpp:282] Agent using credential for: test-principal
> I0627 15:20:33.752419 30774 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credentials'
> I0627 15:20:33.752648 30774 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> I0627 15:20:33.752821 30774 http.cpp:974] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0627 15:20:33.753873 30774 slave.cpp:553] Agent resources: [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 15:20:33.754041 30774 slave.cpp:561] Agent attributes: [ ]
> I0627 15:20:33.754051 30774 slave.cpp:566] Agent hostname: 0b1049f05548
> I0627 15:20:33.754200 30788 status_update_manager.cpp:177] Pausing sending status updates
> I0627 15:20:33.755672 30792 state.cpp:64] Recovering state from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta'
> I0627 15:20:33.755934 30790 status_update_manager.cpp:203] Recovering status update manager
> I0627 15:20:33.756114 30789 containerizer.cpp:582] Recovering containerizer
> I0627 15:20:33.756492 30778 process.cpp:3779] Handling HTTP event for process 'master' with path: '/master/reserve'
> I0627 15:20:33.757879 30783 provisioner.cpp:416] Provisioner recovery complete
> I0627 15:20:33.758180 30784 slave.cpp:6168] Finished recovery
> I0627 15:20:33.758538 30780 http.cpp:1114] HTTP POST for /master/reserve from 172.17.0.2:44414
> I0627 15:20:33.758766 30784 slave.cpp:6350] Querying resource estimator for oversubscribable resources
> I0627 15:20:33.758973 30795 status_update_manager.cpp:177] Pausing sending status updates
> I0627 15:20:33.758972 30784 slave.cpp:946] New master detected at master@172.17.0.2:44357
> I0627 15:20:33.759085 30784 slave.cpp:981] Detecting new master
> I0627 15:20:33.759176 30784 slave.cpp:6364] Received oversubscribable resources {} from the resource estimator
> I0627 15:20:33.759441 30780 master.cpp:3527] Authorizing principal 'test-principal' to reserve resources '[{"name":"cpus","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":4.0},"type":"SCALAR"}]'
> I0627 15:20:33.761719 30779 master.cpp:8908] Sending updated checkpointed resources cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 to agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.762620 30794 slave.cpp:3426] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role1,test-principal)]):4
> I0627 15:20:33.763795 30775 slave.cpp:1008] Authenticating with master master@172.17.0.2:44357
> I0627 15:20:33.763928 30775 slave.cpp:1019] Using default CRAM-MD5 authenticatee
> I0627 15:20:33.764186 30795 authenticatee.cpp:121] Creating new client SASL connection
> I0627 15:20:33.764468 30796 master.cpp:7640] Authenticating slave(452)@172.17.0.2:44357
> I0627 15:20:33.764649 30785 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(939)@172.17.0.2:44357
> I0627 15:20:33.764925 30795 authenticator.cpp:98] Creating new server SASL connection
> I0627 15:20:33.765175 30777 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0627 15:20:33.765203 30777 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0627 15:20:33.765386 30785 authenticator.cpp:204] Received SASL authentication start
> I0627 15:20:33.765439 30785 authenticator.cpp:326] Authentication requires more steps
> I0627 15:20:33.765538 30784 authenticatee.cpp:259] Received SASL authentication step
> I0627 15:20:33.765709 30789 authenticator.cpp:232] Received SASL authentication step
> I0627 15:20:33.765758 30789 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0627 15:20:33.765774 30789 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0627 15:20:33.765825 30789 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0627 15:20:33.765854 30789 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0627 15:20:33.765867 30789 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.765877 30789 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.765902 30789 authenticator.cpp:318] Authentication success
> I0627 15:20:33.766007 30773 sched.cpp:232] Version: 1.4.0
> I0627 15:20:33.766126 30790 authenticatee.cpp:299] Authentication success
> I0627 15:20:33.766155 30788 master.cpp:7670] Successfully authenticated principal 'test-principal' at slave(452)@172.17.0.2:44357
> I0627 15:20:33.766187 30789 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(939)@172.17.0.2:44357
> I0627 15:20:33.766543 30776 slave.cpp:1103] Successfully authenticated with master master@172.17.0.2:44357
> I0627 15:20:33.766687 30793 sched.cpp:336] New master detected at master@172.17.0.2:44357
> I0627 15:20:33.766753 30793 sched.cpp:407] Authenticating with master master@172.17.0.2:44357
> I0627 15:20:33.766767 30793 sched.cpp:414] Using default CRAM-MD5 authenticatee
> I0627 15:20:33.766770 30776 slave.cpp:1545] Will retry registration in 2.625286ms if necessary
> I0627 15:20:33.766901 30789 master.cpp:5602] Received register agent message from slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.766932 30789 master.cpp:3742] Authorizing agent with principal 'test-principal'
> I0627 15:20:33.766964 30797 authenticatee.cpp:121] Creating new client SASL connection
> I0627 15:20:33.767232 30789 master.cpp:7640] Authenticating scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.767307 30776 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(940)@172.17.0.2:44357
> I0627 15:20:33.767468 30774 master.cpp:5662] Authorized registration of agent at slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.767489 30797 authenticator.cpp:98] Creating new server SASL connection
> I0627 15:20:33.767608 30774 master.cpp:5741] Registering agent at slave(452)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3277b1-S1
> I0627 15:20:33.767666 30778 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0627 15:20:33.767691 30778 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0627 15:20:33.767819 30797 authenticator.cpp:204] Received SASL authentication start
> I0627 15:20:33.767864 30797 authenticator.cpp:326] Authentication requires more steps
> I0627 15:20:33.767958 30786 authenticatee.cpp:259] Received SASL authentication step
> I0627 15:20:33.767989 30781 registrar.cpp:493] Applied 1 operations in 89291ns; attempting to update the registry
> I0627 15:20:33.768164 30788 authenticator.cpp:232] Received SASL authentication step
> I0627 15:20:33.768187 30788 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0627 15:20:33.768198 30788 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0627 15:20:33.768239 30788 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0627 15:20:33.768260 30788 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0627 15:20:33.768267 30788 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.768272 30788 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0627 15:20:33.768285 30788 authenticator.cpp:318] Authentication success
> I0627 15:20:33.768394 30792 authenticatee.cpp:299] Authentication success
> I0627 15:20:33.768615 30777 master.cpp:7670] Successfully authenticated principal 'test-principal' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.768641 30790 sched.cpp:513] Successfully authenticated with master master@172.17.0.2:44357
> I0627 15:20:33.768661 30790 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.2:44357
> I0627 15:20:33.768661 30776 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(940)@172.17.0.2:44357
> I0627 15:20:33.768782 30781 registrar.cpp:550] Successfully updated the registry in 722176ns
> I0627 15:20:33.768887 30790 sched.cpp:869] Will retry registration in 424.478509ms if necessary
> I0627 15:20:33.769176 30785 master.cpp:2853] Received SUBSCRIBE call for framework 'default' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.769222 30785 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }'
> I0627 15:20:33.770375 30796 slave.cpp:1545] Will retry registration in 37.054423ms if necessary
> I0627 15:20:33.770567 30785 master.cpp:5788] Admitted agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.771241 30784 slave.cpp:4866] Received ping from slave-observer(450)@172.17.0.2:44357
> I0627 15:20:33.771467 30787 slave.cpp:1149] Registered with master master@172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S1
> I0627 15:20:33.771585 30789 status_update_manager.cpp:184] Resuming sending status updates
> I0627 15:20:33.771392 30785 master.cpp:5819] Registered agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 15:20:33.771682 30777 hierarchical.cpp:587] Added agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 (0b1049f05548) with cpus:3; mem:95614; disk:367489; ports:[31000-32000] (allocated: {})
> I0627 15:20:33.771832 30787 slave.cpp:1169] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta/slaves/d8d232e5-1689-4780-b232-c91e5c3277b1-S1/slave.info'
> I0627 15:20:33.771932 30777 hierarchical.cpp:1938] No allocations performed
> I0627 15:20:33.771953 30785 master.cpp:5602] Received register agent message from slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.771975 30777 hierarchical.cpp:1493] Performed allocation for 1 agents in 164163ns
> I0627 15:20:33.771996 30785 master.cpp:3742] Authorizing agent with principal 'test-principal'
> I0627 15:20:33.772150 30787 slave.cpp:1207] Forwarding total oversubscribed resources {}
> I0627 15:20:33.772339 30785 master.cpp:2933] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
> I0627 15:20:33.773007 30785 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
> I0627 15:20:33.773047 30794 sched.cpp:759] Framework registered with d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.773095 30794 sched.cpp:773] Scheduler::registered took 31019ns
> I0627 15:20:33.773164 30785 master.cpp:5662] Authorized registration of agent at slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.773227 30776 hierarchical.cpp:301] Added framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.773247 30785 master.cpp:5719] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) already registered, resending acknowledgement
> W0627 15:20:33.773438 30783 slave.cpp:1193] Already registered with master master@172.17.0.2:44357
> I0627 15:20:33.773470 30783 slave.cpp:1207] Forwarding total oversubscribed resources {}
> I0627 15:20:33.773676 30781 master.cpp:6508] Received update of agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) with total oversubscribed resources {}
> I0627 15:20:33.774871 30776 hierarchical.cpp:2028] No inverse offers to send out!
> I0627 15:20:33.774912 30776 hierarchical.cpp:1493] Performed allocation for 2 agents in 1.518176ms
> I0627 15:20:33.776294 30783 master.cpp:7470] Sending 2 offers to framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.776959 30776 sched.cpp:933] Scheduler::resourceOffers took 133421ns
> /mesos/src/tests/persistent_volume_endpoints_tests.cpp:1859: Failure
> Value of: offeredSlaveId == slaveId1 || offeredSlaveId == slaveId2
> Actual: false
> Expected: true
> I0627 15:20:33.778265 30791 master.cpp:1430] Framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 disconnected
> I0627 15:20:33.778303 30791 master.cpp:3203] Deactivating framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.779554 30787 hierarchical.cpp:410] Deactivated framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.779958 30791 master.cpp:3180] Disconnecting framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.780009 30791 master.cpp:1445] Giving framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 0ns to failover
> I0627 15:20:33.780483 30787 hierarchical.cpp:1177] Recovered ports(allocated: role1):[31000-32000]; mem(allocated: role1):95614; disk(allocated: role1):367489; cpus(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):4 (total: ports:[31000-32000]; mem:95614; disk:367489; cpus(reservations: [(DYNAMIC,role1,test-principal)]):4, allocated: {}) on agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.781185 30787 hierarchical.cpp:1177] Recovered cpus(allocated: role1):3; mem(allocated: role1):95614; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000] (total: cpus:3; mem:95614; disk:367489; ports:[31000-32000], allocated: {}) on agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.781599 30789 master.cpp:7306] Framework failover timeout, removing framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.781625 30789 master.cpp:8163] Removing framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357
> I0627 15:20:33.781790 30787 slave.cpp:3136] Asked to shut down framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357
> I0627 15:20:33.781803 30791 slave.cpp:3136] Asked to shut down framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357
> I0627 15:20:33.781817 30787 slave.cpp:3151] Cannot shut down unknown framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.781831 30791 slave.cpp:3151] Cannot shut down unknown framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.782289 30780 hierarchical.cpp:353] Removed framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000
> I0627 15:20:33.788432 30787 slave.cpp:818] Agent terminating
> I0627 15:20:33.788750 30796 master.cpp:1316] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) disconnected
> I0627 15:20:33.788781 30796 master.cpp:3240] Disconnecting agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.788859 30796 master.cpp:3259] Deactivating agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.788995 30777 hierarchical.cpp:715] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1 deactivated
> I0627 15:20:33.796249 30779 hierarchical.cpp:1938] No allocations performed
> I0627 15:20:33.796330 30779 hierarchical.cpp:1493] Performed allocation for 2 agents in 319501ns
> I0627 15:20:33.798933 30796 slave.cpp:818] Agent terminating
> I0627 15:20:33.799327 30795 master.cpp:1316] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) disconnected
> I0627 15:20:33.799360 30795 master.cpp:3240] Disconnecting agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.799438 30795 master.cpp:3259] Deactivating agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548)
> I0627 15:20:33.799567 30787 hierarchical.cpp:715] Agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0 deactivated
> I0627 15:20:33.804204 30779 master.cpp:1158] Master terminating
> I0627 15:20:33.810475 30780 hierarchical.cpp:620] Removed agent d8d232e5-1689-4780-b232-c91e5c3277b1-S1
> I0627 15:20:33.811208 30780 hierarchical.cpp:620] Removed agent d8d232e5-1689-4780-b232-c91e5c3277b1-S0
> /mesos/3rdparty/libprocess/include/process/gmock.hpp:441: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <B8-F3 06-40 86-2B 00-00>, 1, 1)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval (138 ms)
> {code}
> [~neilconway] Can you take a look at this? This has been terribly flaky on ASF CI.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)