[
https://issues.apache.org/jira/browse/MESOS-7739?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Benjamin Mahler updated MESOS-7739:
-----------------------------------
Description:
Observed this on ASF CI.
Seems a bit different from MESOS-7441.
{code}
[ RUN ] RegisterSlaveValidationTest.DropInvalidReregistration
I0629 05:23:17.367363 2252 cluster.cpp:162] Creating default 'local' authorizer
I0629 05:23:17.370198 2276 master.cpp:436] Master
25091bef-3845-4bb6-ae23-e18ac0f4d174 (b3c104d65da7) started on 172.17.0.3:42034
I0629 05:23:17.370234 2276 master.cpp:438] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" -
-allocator="HierarchicalDRF" --authenticate_agents="true"
--authenticate_frameworks="true" --authenticate_http_frameworks="true"
--authenticate_http_readonly="true" --au
thenticate_http_readwrite="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/V0UvSM/credentials"
--framework_sorter="drf" --help="false" --hostn
ame_lookup="true" --http_authenticators="basic"
--http_framework_authenticators="basic" --initialize_driver_logging="true"
--log_auto_initialize="true" --logbufsecs="0"
--logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-1.3.1/_inst/share/mesos/webui"
--work_dir="/tmp/V0UvSM/master" --zk_session_timeout="10secs"
I0629 05:23:17.370513 2276 master.cpp:488] Master only allowing authenticated
frameworks to register
I0629 05:23:17.370525 2276 master.cpp:502] Master only allowing authenticated
agents to register
I0629 05:23:17.370534 2276 master.cpp:515] Master only allowing authenticated
HTTP frameworks to register
I0629 05:23:17.370543 2276 credentials.hpp:37] Loading credentials for
authentication from '/tmp/V0UvSM/credentials'
I0629 05:23:17.370806 2276 master.cpp:560] Using default 'crammd5'
authenticator
I0629 05:23:17.370929 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0629 05:23:17.371073 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0629 05:23:17.371193 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0629 05:23:17.371318 2276 master.cpp:640] Authorization enabled
I0629 05:23:17.371455 2272 hierarchical.cpp:158] Initialized hierarchical
allocator process
I0629 05:23:17.371477 2290 whitelist_watcher.cpp:77] No whitelist given
I0629 05:23:17.373731 2277 master.cpp:2161] Elected as the leading master!
I0629 05:23:17.373760 2277 master.cpp:1700] Recovering from registrar
I0629 05:23:17.373891 2280 registrar.cpp:345] Recovering registrar
I0629 05:23:17.374527 2280 registrar.cpp:389] Successfully fetched the
registry (0B) in 593152ns
I0629 05:23:17.374625 2280 registrar.cpp:493] Applied 1 operations in 19216ns;
attempting to update the registry
I0629 05:23:17.375228 2280 registrar.cpp:550] Successfully updated the
registry in 555008ns
I0629 05:23:17.375336 2280 registrar.cpp:422] Successfully recovered registrar
I0629 05:23:17.375826 2282 hierarchical.cpp:185] Skipping recovery of
hierarchical allocator: nothing to recover
I0629 05:23:17.375850 2290 master.cpp:1799] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
I0629 05:23:17.380674 2252 containerizer.cpp:221] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
W0629 05:23:17.381237 2252 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
W0629 05:23:17.381350 2252 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I0629 05:23:17.381384 2252 provisioner.cpp:249] Using default backend 'copy'
I0629 05:23:17.383884 2252 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:23:17.385763 2281 slave.cpp:231] Mesos agent started on
(287)@172.17.0.3:42034
I0629 05:23:17.385787 2281 slave.cpp:232] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_executors="true"
--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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/is:
olators/docker/volume" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_secret_key="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/executor_secret_key"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/mesos/mesos-1.3.1/_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:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i"
--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/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx"
I0629 05:23:17.386165 2281 credentials.hpp:86] Loading credential for
authentication from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/credential'
I0629 05:23:17.386319 2281 slave.cpp:264] Agent using credential for:
test-principal
I0629 05:23:17.386339 2281 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials'
I0629 05:23:17.386600 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0629 05:23:17.386703 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0629 05:23:17.386885 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0629 05:23:17.386973 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0629 05:23:17.387302 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0629 05:23:17.387409 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0629 05:23:17.388684 2281 slave.cpp:531] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:23:17.388783 2281 slave.cpp:539] Agent attributes: [ ]
I0629 05:23:17.388801 2281 slave.cpp:544] Agent hostname: b3c104d65da7
I0629 05:23:17.388916 2294 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.390480 2288 state.cpp:62] Recovering state from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta'
I0629 05:23:17.390751 2275 status_update_manager.cpp:203] Recovering status
update manager
I0629 05:23:17.391083 2286 containerizer.cpp:608] Recovering containerizer
I0629 05:23:17.392966 2285 provisioner.cpp:410] Provisioner recovery complete
I0629 05:23:17.393373 2272 slave.cpp:6075] Finished recovery
I0629 05:23:17.393777 2272 slave.cpp:6257] Querying resource estimator for
oversubscribable resources
I0629 05:23:17.394049 2284 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.394065 2272 slave.cpp:924] New master detected at
master@172.17.0.3:42034
I0629 05:23:17.394129 2272 slave.cpp:959] Detecting new master
I0629 05:23:17.394268 2272 slave.cpp:6271] Received oversubscribable resources
{} from the resource estimator
I0629 05:23:17.399830 2292 slave.cpp:986] Authenticating with master
master@172.17.0.3:42034
I0629 05:23:17.399900 2292 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:23:17.400095 2289 authenticatee.cpp:121] Creating new client SASL
connection
I0629 05:23:17.400344 2275 master.cpp:7475] Authenticating
slave(287)@172.17.0.3:42034
I0629 05:23:17.400452 2282 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(624)@172.17.0.3:42034
I0629 05:23:17.400650 2271 authenticator.cpp:98] Creating new server SASL
connection
I0629 05:23:17.400858 2294 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0629 05:23:17.400883 2294 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0629 05:23:17.400981 2291 authenticator.cpp:204] Received SASL authentication
start
I0629 05:23:17.401043 2291 authenticator.cpp:326] Authentication requires more
steps
I0629 05:23:17.401151 2293 authenticatee.cpp:259] Received SASL authentication
step
I0629 05:23:17.401382 2283 authenticator.cpp:232] Received SASL authentication
step
I0629 05:23:17.401419 2283 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0629 05:23:17.401434 2283 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0629 05:23:17.401470 2283 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0629 05:23:17.401492 2283 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0629 05:23:17.401506 2283 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.401515 2283 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.401532 2283 authenticator.cpp:318] Authentication success
I0629 05:23:17.401620 2289 authenticatee.cpp:299] Authentication success
I0629 05:23:17.401682 2281 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(287)@172.17.0.3:42034
I0629 05:23:17.401913 2273 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(624)@172.17.0.3:42034
I0629 05:23:17.401921 2284 slave.cpp:1081] Successfully authenticated with
master master@172.17.0.3:42034
I0629 05:23:17.402212 2284 slave.cpp:1509] Will retry registration in
1.256299ms if necessary
I0629 05:23:17.402345 2294 master.cpp:5429] Received register agent message
from slave(287)@172.17.0.3:42034 (b3c104d65da7)
I0629 05:23:17.402477 2294 master.cpp:3659] Authorizing agent with principal
'test-principal'
I0629 05:23:17.402930 2271 master.cpp:5564] Registering agent at
slave(287)@172.17.0.3:42034 (b3c104d65da7) with id
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.403379 2281 registrar.cpp:493] Applied 1 operations in 62566ns;
attempting to update the registry
I0629 05:23:17.404207 2281 registrar.cpp:550] Successfully updated the
registry in 769024ns
I0629 05:23:17.404608 2286 slave.cpp:1509] Will retry registration in
25.850396ms if necessary
I0629 05:23:17.405179 2276 slave.cpp:4794] Received ping from
slave-observer(289)@172.17.0.3:42034
I0629 05:23:17.405144 2294 master.cpp:5639] Registered agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:23:17.405441 2276 slave.cpp:1127] Registered with master
master@172.17.0.3:42034; given agent ID 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.405465 2276 fetcher.cpp:94] Clearing fetcher cache
I0629 05:23:17.405508 2293 hierarchical.cpp:525] Added agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 (b3c104d65da7) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0629 05:23:17.405594 2294 master.cpp:5429] Received register agent message
from slave(287)@172.17.0.3:42034 (b3c104d65da7)
I0629 05:23:17.405743 2294 master.cpp:3659] Authorizing agent with principal
'test-principal'
I0629 05:23:17.405750 2288 status_update_manager.cpp:184] Resuming sending
status updates
I0629 05:23:17.405933 2293 hierarchical.cpp:1850] No allocations performed
I0629 05:23:17.405971 2276 slave.cpp:1155] Checkpointing SlaveInfo to
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
I0629 05:23:17.405989 2293 hierarchical.cpp:1434] Performed allocation for 1
agents in 192285ns
I0629 05:23:17.406347 2276 slave.cpp:1193] Forwarding total oversubscribed
resources {}
I0629 05:23:17.406415 2271 master.cpp:5542] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) already registered, resending acknowledgement
I0629 05:23:17.406491 2276 slave.cpp:924] New master detected at
master@172.17.0.3:42034
I0629 05:23:17.406496 2280 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.406548 2276 slave.cpp:959] Detecting new master
I0629 05:23:17.406570 2271 master.cpp:6324] Received update of agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with total oversubscribed resources {}
I0629 05:23:17.406694 2276 slave.cpp:1127] Registered with master
master@172.17.0.3:42034; given agent ID 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.406720 2276 fetcher.cpp:94] Clearing fetcher cache
I0629 05:23:17.406842 2275 status_update_manager.cpp:184] Resuming sending
status updates
I0629 05:23:17.406961 2276 slave.cpp:1155] Checkpointing SlaveInfo to
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
I0629 05:23:17.407268 2276 slave.cpp:1193] Forwarding total oversubscribed
resources {}
I0629 05:23:17.407431 2278 master.cpp:6324] Received update of agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with total oversubscribed resources {}
I0629 05:23:17.413727 2276 slave.cpp:986] Authenticating with master
master@172.17.0.3:42034
I0629 05:23:17.413785 2276 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:23:17.413978 2278 authenticatee.cpp:121] Creating new client SASL
connection
I0629 05:23:17.414268 2290 master.cpp:7475] Authenticating
slave(287)@172.17.0.3:42034
I0629 05:23:17.414409 2273 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(625)@172.17.0.3:42034
I0629 05:23:17.414752 2292 authenticator.cpp:98] Creating new server SASL
connection
I0629 05:23:17.414988 2272 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0629 05:23:17.415014 2272 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0629 05:23:17.415158 2278 authenticator.cpp:204] Received SASL authentication
start
I0629 05:23:17.415225 2278 authenticator.cpp:326] Authentication requires more
steps
I0629 05:23:17.415345 2285 authenticatee.cpp:259] Received SASL authentication
step
I0629 05:23:17.415586 2271 authenticator.cpp:232] Received SASL authentication
step
I0629 05:23:17.415616 2271 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0629 05:23:17.415629 2271 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0629 05:23:17.415665 2271 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0629 05:23:17.415689 2271 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0629 05:23:17.415701 2271 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.415711 2271 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.415726 2271 authenticator.cpp:318] Authentication success
I0629 05:23:17.415807 2278 authenticatee.cpp:299] Authentication success
I0629 05:23:17.415865 2294 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(287)@172.17.0.3:42034
I0629 05:23:17.415910 2288 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(625)@172.17.0.3:42034
I0629 05:23:17.416126 2274 slave.cpp:1081] Successfully authenticated with
master master@172.17.0.3:42034
I0629 05:23:18.372947 2275 hierarchical.cpp:1850] No allocations performed
I0629 05:23:18.373133 2275 hierarchical.cpp:1434] Performed allocation for 1
agents in 578948ns
I0629 05:23:19.374871 2289 hierarchical.cpp:1850] No allocations performed
I0629 05:23:19.375056 2289 hierarchical.cpp:1434] Performed allocation for 1
agents in 520444ns
I0629 05:23:20.375833 2290 hierarchical.cpp:1850] No allocations performed
I0629 05:23:20.375975 2290 hierarchical.cpp:1434] Performed allocation for 1
agents in 435113ns
I0629 05:23:21.377182 2279 hierarchical.cpp:1850] No allocations performed
I0629 05:23:21.377399 2279 hierarchical.cpp:1434] Performed allocation for 1
agents in 639655ns
I0629 05:23:22.378278 2277 hierarchical.cpp:1850] No allocations performed
I0629 05:23:22.378437 2277 hierarchical.cpp:1434] Performed allocation for 1
agents in 427151ns
I0629 05:23:23.380287 2292 hierarchical.cpp:1850] No allocations performed
I0629 05:23:23.380481 2292 hierarchical.cpp:1434] Performed allocation for 1
agents in 578747ns
I0629 05:23:24.381932 2273 hierarchical.cpp:1850] No allocations performed
I0629 05:23:24.382097 2273 hierarchical.cpp:1434] Performed allocation for 1
agents in 476981ns
I0629 05:23:25.383314 2275 hierarchical.cpp:1850] No allocations performed
I0629 05:23:25.383499 2275 hierarchical.cpp:1434] Performed allocation for 1
agents in 500084ns
I0629 05:23:26.384625 2281 hierarchical.cpp:1850] No allocations performed
I0629 05:23:26.384855 2281 hierarchical.cpp:1434] Performed allocation for 1
agents in 515354ns
I0629 05:23:27.385927 2291 hierarchical.cpp:1850] No allocations performed
I0629 05:23:27.386139 2291 hierarchical.cpp:1434] Performed allocation for 1
agents in 562796ns
I0629 05:23:28.387132 2285 hierarchical.cpp:1850] No allocations performed
I0629 05:23:28.387297 2285 hierarchical.cpp:1434] Performed allocation for 1
agents in 438370ns
I0629 05:23:29.388170 2286 hierarchical.cpp:1850] No allocations performed
I0629 05:23:29.388309 2286 hierarchical.cpp:1434] Performed allocation for 1
agents in 317943ns
I0629 05:23:30.389729 2278 hierarchical.cpp:1850] No allocations performed
I0629 05:23:30.389909 2278 hierarchical.cpp:1434] Performed allocation for 1
agents in 475524ns
I0629 05:23:31.390977 2280 hierarchical.cpp:1850] No allocations performed
I0629 05:23:31.391084 2280 hierarchical.cpp:1434] Performed allocation for 1
agents in 266216ns
I0629 05:23:32.391724 2287 hierarchical.cpp:1850] No allocations performed
I0629 05:23:32.391827 2287 hierarchical.cpp:1434] Performed allocation for 1
agents in 270448ns
I0629 05:23:32.394664 2276 slave.cpp:6257] Querying resource estimator for
oversubscribable resources
I0629 05:23:32.395167 2293 slave.cpp:6271] Received oversubscribable resources
{} from the resource estimator
I0629 05:23:32.406095 2288 slave.cpp:4794] Received ping from
slave-observer(289)@172.17.0.3:42034
../../src/tests/master_validation_tests.cpp:3757: Failure
Failed to wait 15secs for reregisterSlaveMessage
I0629 05:23:32.409525 2291 slave.cpp:796] Agent terminating
I0629 05:23:32.410306 2292 master.cpp:1313] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) disconnected
I0629 05:23:32.410360 2292 master.cpp:3197] Disconnecting agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7)
I0629 05:23:32.410907 2292 master.cpp:3216] Deactivating agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7)
I0629 05:23:32.411128 2288 hierarchical.cpp:653] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 deactivated
I0629 05:23:32.418536 2278 master.cpp:1155] Master terminating
I0629 05:23:32.419867 2289 hierarchical.cpp:558] Removed agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <58-BF 04-20 F5-7F 00-00>, 1,
1-byte object <E8>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] RegisterSlaveValidationTest.DropInvalidReregistration (15061 ms)
{code}
Observed on macOS when testing 1.3.1:
{noformat}
[ RUN ] RegisterSlaveValidationTest.DropInvalidReregistration
I0802 13:34:21.685421 2516382656 cluster.cpp:162] Creating default 'local'
authorizer
I0802 13:34:21.686971 224620544 master.cpp:436] Master
21402191-4b94-4a3c-9c84-cf9942b0b81a (192.168.1.15) started on
192.168.1.15:53913
I0802 13:34:21.686991 224620544 master.cpp:438] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticators="crammd5"
--authorizers="local"
--credentials="/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/master"
--zk_session_timeout="10secs"
I0802 13:34:21.687160 224620544 master.cpp:488] Master only allowing
authenticated frameworks to register
I0802 13:34:21.687182 224620544 master.cpp:502] Master only allowing
authenticated agents to register
I0802 13:34:21.687191 224620544 master.cpp:515] Master only allowing
authenticated HTTP frameworks to register
I0802 13:34:21.687198 224620544 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/credentials'
I0802 13:34:21.687373 224620544 master.cpp:560] Using default 'crammd5'
authenticator
I0802 13:34:21.687434 224620544 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0802 13:34:21.687558 224620544 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0802 13:34:21.687672 224620544 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0802 13:34:21.687784 224620544 master.cpp:640] Authorization enabled
I0802 13:34:21.689018 227303424 master.cpp:2161] Elected as the leading master!
I0802 13:34:21.689031 227303424 master.cpp:1700] Recovering from registrar
I0802 13:34:21.689425 224083968 registrar.cpp:389] Successfully fetched the
registry (0B) in 326912ns
I0802 13:34:21.689481 224083968 registrar.cpp:493] Applied 1 operations in
17us; attempting to update the registry
I0802 13:34:21.689767 224083968 registrar.cpp:550] Successfully updated the
registry in 263168ns
I0802 13:34:21.689812 224083968 registrar.cpp:422] Successfully recovered
registrar
I0802 13:34:21.690094 226766848 master.cpp:1799] Recovered 0 agents from the
registry (135B); allowing 10mins for agents to re-register
I0802 13:34:21.692261 2516382656 containerizer.cpp:221] Using isolation:
posix/cpu,posix/mem,filesystem/posix
I0802 13:34:21.692390 2516382656 provisioner.cpp:249] Using default backend
'copy'
I0802 13:34:21.693034 2516382656 cluster.cpp:448] Creating default 'local'
authorizer
I0802 13:34:21.693660 226766848 slave.cpp:231] Mesos agent started on
(5)@192.168.1.15:53913
I0802 13:34:21.693699 226766848 slave.cpp:232] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/mesos/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/mesos/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/Users/bmahler/Downloads/mesos-1.3.1/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:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--runtime_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_JdMGIN"
I0802 13:34:21.693886 226766848 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/credential'
I0802 13:34:21.693975 226766848 slave.cpp:264] Agent using credential for:
test-principal
I0802 13:34:21.693989 226766848 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/http_credentials'
I0802 13:34:21.694102 226766848 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0802 13:34:21.694186 226766848 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0802 13:34:21.694964 226766848 slave.cpp:531] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0802 13:34:21.695008 226766848 slave.cpp:539] Agent attributes: [ ]
I0802 13:34:21.695016 226766848 slave.cpp:544] Agent hostname: 192.168.1.15
I0802 13:34:21.695087 227840000 status_update_manager.cpp:177] Pausing sending
status updates
I0802 13:34:21.695673 225693696 state.cpp:62] Recovering state from
'/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_JdMGIN/meta'
I0802 13:34:21.695814 226230272 status_update_manager.cpp:203] Recovering
status update manager
I0802 13:34:21.695937 225693696 containerizer.cpp:608] Recovering containerizer
I0802 13:34:21.696552 224620544 provisioner.cpp:410] Provisioner recovery
complete
I0802 13:34:21.696770 226766848 slave.cpp:6075] Finished recovery
I0802 13:34:21.697232 225157120 status_update_manager.cpp:177] Pausing sending
status updates
I0802 13:34:21.697247 226766848 slave.cpp:924] New master detected at
master@192.168.1.15:53913
I0802 13:34:21.697314 226766848 slave.cpp:959] Detecting new master
I0802 13:34:21.706558 227303424 slave.cpp:986] Authenticating with master
master@192.168.1.15:53913
I0802 13:34:21.706626 227303424 slave.cpp:997] Using default CRAM-MD5
authenticatee
I0802 13:34:21.706876 227840000 authenticatee.cpp:121] Creating new client SASL
connection
I0802 13:34:21.707221 227303424 master.cpp:7475] Authenticating
slave(5)@192.168.1.15:53913
I0802 13:34:21.707667 224083968 authenticator.cpp:98] Creating new server SASL
connection
I0802 13:34:21.707852 227840000 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0802 13:34:21.707921 227840000 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0802 13:34:21.708161 227840000 authenticator.cpp:204] Received SASL
authentication start
I0802 13:34:21.708250 227840000 authenticator.cpp:326] Authentication requires
more steps
I0802 13:34:21.708449 225693696 authenticatee.cpp:259] Received SASL
authentication step
I0802 13:34:21.708734 227303424 authenticator.cpp:232] Received SASL
authentication step
I0802 13:34:21.708827 227303424 authenticator.cpp:318] Authentication success
I0802 13:34:21.708992 225693696 authenticatee.cpp:299] Authentication success
I0802 13:34:21.709059 224083968 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(5)@192.168.1.15:53913
I0802 13:34:21.709574 226766848 slave.cpp:1081] Successfully authenticated with
master master@192.168.1.15:53913
I0802 13:34:21.709900 224083968 master.cpp:5429] Received register agent
message from slave(5)@192.168.1.15:53913 (192.168.1.15)
I0802 13:34:21.709947 224083968 master.cpp:3659] Authorizing agent with
principal 'test-principal'
I0802 13:34:21.710321 225693696 master.cpp:5564] Registering agent at
slave(5)@192.168.1.15:53913 (192.168.1.15) with id
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0
I0802 13:34:21.710543 224620544 registrar.cpp:493] Applied 1 operations in
47us; attempting to update the registry
I0802 13:34:21.710937 224620544 registrar.cpp:550] Successfully updated the
registry in 355840ns
I0802 13:34:21.711361 225157120 master.cpp:5639] Registered agent
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
(192.168.1.15) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0802 13:34:21.711501 224620544 hierarchical.cpp:525] Added agent
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 (192.168.1.15) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0802 13:34:21.711558 227303424 slave.cpp:1127] Registered with master
master@192.168.1.15:53913; given agent ID
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0
I0802 13:34:21.711809 224620544 status_update_manager.cpp:184] Resuming sending
status updates
I0802 13:34:21.712311 227303424 slave.cpp:1193] Forwarding total oversubscribed
resources {}
I0802 13:34:21.712429 224083968 master.cpp:6324] Received update of agent
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
(192.168.1.15) with total oversubscribed resources {}
I0802 13:34:21.712707 226766848 slave.cpp:924] New master detected at
master@192.168.1.15:53913
I0802 13:34:21.712712 226230272 status_update_manager.cpp:177] Pausing sending
status updates
I0802 13:34:21.712759 226766848 slave.cpp:959] Detecting new master
I0802 13:34:21.720463 224620544 slave.cpp:986] Authenticating with master
master@192.168.1.15:53913
I0802 13:34:21.720505 224620544 slave.cpp:997] Using default CRAM-MD5
authenticatee
I0802 13:34:21.720631 225693696 authenticatee.cpp:121] Creating new client SASL
connection
I0802 13:34:21.720824 226766848 master.cpp:7475] Authenticating
slave(5)@192.168.1.15:53913
I0802 13:34:21.721016 224620544 authenticator.cpp:98] Creating new server SASL
connection
I0802 13:34:21.721148 227840000 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0802 13:34:21.721169 227840000 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0802 13:34:21.721251 227840000 authenticator.cpp:204] Received SASL
authentication start
I0802 13:34:21.721302 227840000 authenticator.cpp:326] Authentication requires
more steps
I0802 13:34:21.721350 227840000 authenticatee.cpp:259] Received SASL
authentication step
I0802 13:34:21.721472 226766848 authenticator.cpp:232] Received SASL
authentication step
I0802 13:34:21.721508 226766848 authenticator.cpp:318] Authentication success
I0802 13:34:21.721577 227303424 authenticatee.cpp:299] Authentication success
I0802 13:34:21.721617 227840000 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(5)@192.168.1.15:53913
I0802 13:34:21.721856 225157120 slave.cpp:1081] Successfully authenticated with
master master@192.168.1.15:53913
I0802 13:34:21.722730 227303424 master.cpp:5708] Received re-register agent
message from agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
slave(5)@192.168.1.15:53913 (192.168.1.15)
I0802 13:34:21.722759 227303424 master.cpp:3659] Authorizing agent with
principal 'test-principal'
I0802 13:34:21.735528 227303424 master.cpp:5691] Ignoring re-register agent
message from agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
slave(5)@192.168.1.15:53913 (192.168.1.15) as re-registration is already in
progress
I0802 13:34:21.735604 227303424 master.cpp:5824] Re-registering agent
21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
(192.168.1.15)
I0802 13:34:21.735736 227303424 master.cpp:6233] Sending updated checkpointed
resources {} to agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
slave(5)@192.168.1.15:53913 (192.168.1.15)
../3rdparty/libprocess/include/process/gmock.hpp:601: Failure
Mock function called more times than expected - returning default value.
Function call: filter(@0x7f92ecd8eef0 16-byte object <B0-A8 07-11 01-00
00-00 90-C4 D8-EC 92-7F 00-00>)
Returns: false
Expected: to be never called
Actual: called once - over-saturated and active
*** Aborted at 1501706061 (unix time) try "date -d @1501706061" if you are
using GNU date ***
PC: @ 0x10a76f480 testing::UnitTest::AddTestPartResult()
*** SIGSEGV (@0x0) received by PID 62261 (TID 0x70000d949000) stack trace: ***
@ 0x7fff8d2c4b3a _sigtramp
@ 0x17 (unknown)
@ 0x10a76ec87 testing::internal::AssertHelper::operator=()
@ 0x10a7c6ef7
testing::internal::GoogleTestFailureReporter::ReportFailure()
@ 0x1089ede65 testing::internal::Expect()
@ 0x10a7badd5
testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
@ 0x1089f3458 testing::internal::FunctionMockerBase<>::InvokeWith()
@ 0x1089f3403 testing::internal::FunctionMocker<>::Invoke()
@ 0x1089ddb85 process::MockFilter::filter()
@ 0x1089f3851 process::TestsFilter::handle<>()
@ 0x1089dabfd process::TestsFilter::filter()
@ 0x1105ea85f
process::ProcessManager::resume()::FilterVisitor::visit()
@ 0x10da9991e process::MessageEvent::visit()
@ 0x110599e78 process::ProcessManager::resume()
@ 0x1106759b0
process::ProcessManager::init_threads()::$_1::operator()()
@ 0x1106755d2
_ZNSt3__114__thread_proxyINS_5tupleIJZN7process14ProcessManager12init_threadsEvE3$_1EEEEEPvS6_
@ 0x7fff8d2ce93b _pthread_body
@ 0x7fff8d2ce887 _pthread_start
@ 0x7fff8d2ce08d thread_start
[1] 62261 segmentation fault ./bin/mesos-tests.sh --gtest_repeat=-1
--gtest_break_on_failure --verbose
{noformat}
was:
Observed this on ASF CI.
Seems a bit different from MESOS-7441.
{code}
[ RUN ] RegisterSlaveValidationTest.DropInvalidReregistration
I0629 05:23:17.367363 2252 cluster.cpp:162] Creating default 'local' authorizer
I0629 05:23:17.370198 2276 master.cpp:436] Master
25091bef-3845-4bb6-ae23-e18ac0f4d174 (b3c104d65da7) started on 172.17.0.3:42034
I0629 05:23:17.370234 2276 master.cpp:438] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" -
-allocator="HierarchicalDRF" --authenticate_agents="true"
--authenticate_frameworks="true" --authenticate_http_frameworks="true"
--authenticate_http_readonly="true" --au
thenticate_http_readwrite="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/V0UvSM/credentials"
--framework_sorter="drf" --help="false" --hostn
ame_lookup="true" --http_authenticators="basic"
--http_framework_authenticators="basic" --initialize_driver_logging="true"
--log_auto_initialize="true" --logbufsecs="0"
--logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-1.3.1/_inst/share/mesos/webui"
--work_dir="/tmp/V0UvSM/master" --zk_session_timeout="10secs"
I0629 05:23:17.370513 2276 master.cpp:488] Master only allowing authenticated
frameworks to register
I0629 05:23:17.370525 2276 master.cpp:502] Master only allowing authenticated
agents to register
I0629 05:23:17.370534 2276 master.cpp:515] Master only allowing authenticated
HTTP frameworks to register
I0629 05:23:17.370543 2276 credentials.hpp:37] Loading credentials for
authentication from '/tmp/V0UvSM/credentials'
I0629 05:23:17.370806 2276 master.cpp:560] Using default 'crammd5'
authenticator
I0629 05:23:17.370929 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0629 05:23:17.371073 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0629 05:23:17.371193 2276 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0629 05:23:17.371318 2276 master.cpp:640] Authorization enabled
I0629 05:23:17.371455 2272 hierarchical.cpp:158] Initialized hierarchical
allocator process
I0629 05:23:17.371477 2290 whitelist_watcher.cpp:77] No whitelist given
I0629 05:23:17.373731 2277 master.cpp:2161] Elected as the leading master!
I0629 05:23:17.373760 2277 master.cpp:1700] Recovering from registrar
I0629 05:23:17.373891 2280 registrar.cpp:345] Recovering registrar
I0629 05:23:17.374527 2280 registrar.cpp:389] Successfully fetched the
registry (0B) in 593152ns
I0629 05:23:17.374625 2280 registrar.cpp:493] Applied 1 operations in 19216ns;
attempting to update the registry
I0629 05:23:17.375228 2280 registrar.cpp:550] Successfully updated the
registry in 555008ns
I0629 05:23:17.375336 2280 registrar.cpp:422] Successfully recovered registrar
I0629 05:23:17.375826 2282 hierarchical.cpp:185] Skipping recovery of
hierarchical allocator: nothing to recover
I0629 05:23:17.375850 2290 master.cpp:1799] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
I0629 05:23:17.380674 2252 containerizer.cpp:221] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
W0629 05:23:17.381237 2252 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
W0629 05:23:17.381350 2252 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I0629 05:23:17.381384 2252 provisioner.cpp:249] Using default backend 'copy'
I0629 05:23:17.383884 2252 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:23:17.385763 2281 slave.cpp:231] Mesos agent started on
(287)@172.17.0.3:42034
I0629 05:23:17.385787 2281 slave.cpp:232] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_executors="true"
--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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/is:
olators/docker/volume" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_secret_key="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/executor_secret_key"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/mesos/mesos-1.3.1/_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:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i"
--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/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx"
I0629 05:23:17.386165 2281 credentials.hpp:86] Loading credential for
authentication from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/credential'
I0629 05:23:17.386319 2281 slave.cpp:264] Agent using credential for:
test-principal
I0629 05:23:17.386339 2281 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials'
I0629 05:23:17.386600 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0629 05:23:17.386703 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0629 05:23:17.386885 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0629 05:23:17.386973 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0629 05:23:17.387302 2281 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0629 05:23:17.387409 2281 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0629 05:23:17.388684 2281 slave.cpp:531] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:23:17.388783 2281 slave.cpp:539] Agent attributes: [ ]
I0629 05:23:17.388801 2281 slave.cpp:544] Agent hostname: b3c104d65da7
I0629 05:23:17.388916 2294 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.390480 2288 state.cpp:62] Recovering state from
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta'
I0629 05:23:17.390751 2275 status_update_manager.cpp:203] Recovering status
update manager
I0629 05:23:17.391083 2286 containerizer.cpp:608] Recovering containerizer
I0629 05:23:17.392966 2285 provisioner.cpp:410] Provisioner recovery complete
I0629 05:23:17.393373 2272 slave.cpp:6075] Finished recovery
I0629 05:23:17.393777 2272 slave.cpp:6257] Querying resource estimator for
oversubscribable resources
I0629 05:23:17.394049 2284 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.394065 2272 slave.cpp:924] New master detected at
master@172.17.0.3:42034
I0629 05:23:17.394129 2272 slave.cpp:959] Detecting new master
I0629 05:23:17.394268 2272 slave.cpp:6271] Received oversubscribable resources
{} from the resource estimator
I0629 05:23:17.399830 2292 slave.cpp:986] Authenticating with master
master@172.17.0.3:42034
I0629 05:23:17.399900 2292 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:23:17.400095 2289 authenticatee.cpp:121] Creating new client SASL
connection
I0629 05:23:17.400344 2275 master.cpp:7475] Authenticating
slave(287)@172.17.0.3:42034
I0629 05:23:17.400452 2282 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(624)@172.17.0.3:42034
I0629 05:23:17.400650 2271 authenticator.cpp:98] Creating new server SASL
connection
I0629 05:23:17.400858 2294 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0629 05:23:17.400883 2294 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0629 05:23:17.400981 2291 authenticator.cpp:204] Received SASL authentication
start
I0629 05:23:17.401043 2291 authenticator.cpp:326] Authentication requires more
steps
I0629 05:23:17.401151 2293 authenticatee.cpp:259] Received SASL authentication
step
I0629 05:23:17.401382 2283 authenticator.cpp:232] Received SASL authentication
step
I0629 05:23:17.401419 2283 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0629 05:23:17.401434 2283 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0629 05:23:17.401470 2283 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0629 05:23:17.401492 2283 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0629 05:23:17.401506 2283 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.401515 2283 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.401532 2283 authenticator.cpp:318] Authentication success
I0629 05:23:17.401620 2289 authenticatee.cpp:299] Authentication success
I0629 05:23:17.401682 2281 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(287)@172.17.0.3:42034
I0629 05:23:17.401913 2273 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(624)@172.17.0.3:42034
I0629 05:23:17.401921 2284 slave.cpp:1081] Successfully authenticated with
master master@172.17.0.3:42034
I0629 05:23:17.402212 2284 slave.cpp:1509] Will retry registration in
1.256299ms if necessary
I0629 05:23:17.402345 2294 master.cpp:5429] Received register agent message
from slave(287)@172.17.0.3:42034 (b3c104d65da7)
I0629 05:23:17.402477 2294 master.cpp:3659] Authorizing agent with principal
'test-principal'
I0629 05:23:17.402930 2271 master.cpp:5564] Registering agent at
slave(287)@172.17.0.3:42034 (b3c104d65da7) with id
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.403379 2281 registrar.cpp:493] Applied 1 operations in 62566ns;
attempting to update the registry
I0629 05:23:17.404207 2281 registrar.cpp:550] Successfully updated the
registry in 769024ns
I0629 05:23:17.404608 2286 slave.cpp:1509] Will retry registration in
25.850396ms if necessary
I0629 05:23:17.405179 2276 slave.cpp:4794] Received ping from
slave-observer(289)@172.17.0.3:42034
I0629 05:23:17.405144 2294 master.cpp:5639] Registered agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:23:17.405441 2276 slave.cpp:1127] Registered with master
master@172.17.0.3:42034; given agent ID 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.405465 2276 fetcher.cpp:94] Clearing fetcher cache
I0629 05:23:17.405508 2293 hierarchical.cpp:525] Added agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 (b3c104d65da7) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0629 05:23:17.405594 2294 master.cpp:5429] Received register agent message
from slave(287)@172.17.0.3:42034 (b3c104d65da7)
I0629 05:23:17.405743 2294 master.cpp:3659] Authorizing agent with principal
'test-principal'
I0629 05:23:17.405750 2288 status_update_manager.cpp:184] Resuming sending
status updates
I0629 05:23:17.405933 2293 hierarchical.cpp:1850] No allocations performed
I0629 05:23:17.405971 2276 slave.cpp:1155] Checkpointing SlaveInfo to
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
I0629 05:23:17.405989 2293 hierarchical.cpp:1434] Performed allocation for 1
agents in 192285ns
I0629 05:23:17.406347 2276 slave.cpp:1193] Forwarding total oversubscribed
resources {}
I0629 05:23:17.406415 2271 master.cpp:5542] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) already registered, resending acknowledgement
I0629 05:23:17.406491 2276 slave.cpp:924] New master detected at
master@172.17.0.3:42034
I0629 05:23:17.406496 2280 status_update_manager.cpp:177] Pausing sending
status updates
I0629 05:23:17.406548 2276 slave.cpp:959] Detecting new master
I0629 05:23:17.406570 2271 master.cpp:6324] Received update of agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with total oversubscribed resources {}
I0629 05:23:17.406694 2276 slave.cpp:1127] Registered with master
master@172.17.0.3:42034; given agent ID 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
I0629 05:23:17.406720 2276 fetcher.cpp:94] Clearing fetcher cache
I0629 05:23:17.406842 2275 status_update_manager.cpp:184] Resuming sending
status updates
I0629 05:23:17.406961 2276 slave.cpp:1155] Checkpointing SlaveInfo to
'/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
I0629 05:23:17.407268 2276 slave.cpp:1193] Forwarding total oversubscribed
resources {}
I0629 05:23:17.407431 2278 master.cpp:6324] Received update of agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) with total oversubscribed resources {}
I0629 05:23:17.413727 2276 slave.cpp:986] Authenticating with master
master@172.17.0.3:42034
I0629 05:23:17.413785 2276 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:23:17.413978 2278 authenticatee.cpp:121] Creating new client SASL
connection
I0629 05:23:17.414268 2290 master.cpp:7475] Authenticating
slave(287)@172.17.0.3:42034
I0629 05:23:17.414409 2273 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(625)@172.17.0.3:42034
I0629 05:23:17.414752 2292 authenticator.cpp:98] Creating new server SASL
connection
I0629 05:23:17.414988 2272 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0629 05:23:17.415014 2272 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0629 05:23:17.415158 2278 authenticator.cpp:204] Received SASL authentication
start
I0629 05:23:17.415225 2278 authenticator.cpp:326] Authentication requires more
steps
I0629 05:23:17.415345 2285 authenticatee.cpp:259] Received SASL authentication
step
I0629 05:23:17.415586 2271 authenticator.cpp:232] Received SASL authentication
step
I0629 05:23:17.415616 2271 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0629 05:23:17.415629 2271 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0629 05:23:17.415665 2271 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0629 05:23:17.415689 2271 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0629 05:23:17.415701 2271 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.415711 2271 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:23:17.415726 2271 authenticator.cpp:318] Authentication success
I0629 05:23:17.415807 2278 authenticatee.cpp:299] Authentication success
I0629 05:23:17.415865 2294 master.cpp:7505] Successfully authenticated
principal 'test-principal' at slave(287)@172.17.0.3:42034
I0629 05:23:17.415910 2288 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(625)@172.17.0.3:42034
I0629 05:23:17.416126 2274 slave.cpp:1081] Successfully authenticated with
master master@172.17.0.3:42034
I0629 05:23:18.372947 2275 hierarchical.cpp:1850] No allocations performed
I0629 05:23:18.373133 2275 hierarchical.cpp:1434] Performed allocation for 1
agents in 578948ns
I0629 05:23:19.374871 2289 hierarchical.cpp:1850] No allocations performed
I0629 05:23:19.375056 2289 hierarchical.cpp:1434] Performed allocation for 1
agents in 520444ns
I0629 05:23:20.375833 2290 hierarchical.cpp:1850] No allocations performed
I0629 05:23:20.375975 2290 hierarchical.cpp:1434] Performed allocation for 1
agents in 435113ns
I0629 05:23:21.377182 2279 hierarchical.cpp:1850] No allocations performed
I0629 05:23:21.377399 2279 hierarchical.cpp:1434] Performed allocation for 1
agents in 639655ns
I0629 05:23:22.378278 2277 hierarchical.cpp:1850] No allocations performed
I0629 05:23:22.378437 2277 hierarchical.cpp:1434] Performed allocation for 1
agents in 427151ns
I0629 05:23:23.380287 2292 hierarchical.cpp:1850] No allocations performed
I0629 05:23:23.380481 2292 hierarchical.cpp:1434] Performed allocation for 1
agents in 578747ns
I0629 05:23:24.381932 2273 hierarchical.cpp:1850] No allocations performed
I0629 05:23:24.382097 2273 hierarchical.cpp:1434] Performed allocation for 1
agents in 476981ns
I0629 05:23:25.383314 2275 hierarchical.cpp:1850] No allocations performed
I0629 05:23:25.383499 2275 hierarchical.cpp:1434] Performed allocation for 1
agents in 500084ns
I0629 05:23:26.384625 2281 hierarchical.cpp:1850] No allocations performed
I0629 05:23:26.384855 2281 hierarchical.cpp:1434] Performed allocation for 1
agents in 515354ns
I0629 05:23:27.385927 2291 hierarchical.cpp:1850] No allocations performed
I0629 05:23:27.386139 2291 hierarchical.cpp:1434] Performed allocation for 1
agents in 562796ns
I0629 05:23:28.387132 2285 hierarchical.cpp:1850] No allocations performed
I0629 05:23:28.387297 2285 hierarchical.cpp:1434] Performed allocation for 1
agents in 438370ns
I0629 05:23:29.388170 2286 hierarchical.cpp:1850] No allocations performed
I0629 05:23:29.388309 2286 hierarchical.cpp:1434] Performed allocation for 1
agents in 317943ns
I0629 05:23:30.389729 2278 hierarchical.cpp:1850] No allocations performed
I0629 05:23:30.389909 2278 hierarchical.cpp:1434] Performed allocation for 1
agents in 475524ns
I0629 05:23:31.390977 2280 hierarchical.cpp:1850] No allocations performed
I0629 05:23:31.391084 2280 hierarchical.cpp:1434] Performed allocation for 1
agents in 266216ns
I0629 05:23:32.391724 2287 hierarchical.cpp:1850] No allocations performed
I0629 05:23:32.391827 2287 hierarchical.cpp:1434] Performed allocation for 1
agents in 270448ns
I0629 05:23:32.394664 2276 slave.cpp:6257] Querying resource estimator for
oversubscribable resources
I0629 05:23:32.395167 2293 slave.cpp:6271] Received oversubscribable resources
{} from the resource estimator
I0629 05:23:32.406095 2288 slave.cpp:4794] Received ping from
slave-observer(289)@172.17.0.3:42034
../../src/tests/master_validation_tests.cpp:3757: Failure
Failed to wait 15secs for reregisterSlaveMessage
I0629 05:23:32.409525 2291 slave.cpp:796] Agent terminating
I0629 05:23:32.410306 2292 master.cpp:1313] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7) disconnected
I0629 05:23:32.410360 2292 master.cpp:3197] Disconnecting agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7)
I0629 05:23:32.410907 2292 master.cpp:3216] Deactivating agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
(b3c104d65da7)
I0629 05:23:32.411128 2288 hierarchical.cpp:653] Agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 deactivated
I0629 05:23:32.418536 2278 master.cpp:1155] Master terminating
I0629 05:23:32.419867 2289 hierarchical.cpp:558] Removed agent
25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <58-BF 04-20 F5-7F 00-00>, 1,
1-byte object <E8>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] RegisterSlaveValidationTest.DropInvalidReregistration (15061 ms)
{code}
Observed on macOS:
> RegisterSlaveValidationTest.DropInvalidReregistration is flaky
> --------------------------------------------------------------
>
> Key: MESOS-7739
> URL: https://issues.apache.org/jira/browse/MESOS-7739
> Project: Mesos
> Issue Type: Bug
> Reporter: Vinod Kone
> Assignee: Neil Conway
> Labels: flaky-test, mesosphere-oncall
>
> Observed this on ASF CI.
> Seems a bit different from MESOS-7441.
> {code}
> [ RUN ] RegisterSlaveValidationTest.DropInvalidReregistration
> I0629 05:23:17.367363 2252 cluster.cpp:162] Creating default 'local'
> authorizer
> I0629 05:23:17.370198 2276 master.cpp:436] Master
> 25091bef-3845-4bb6-ae23-e18ac0f4d174 (b3c104d65da7) started on
> 172.17.0.3:42034
> I0629 05:23:17.370234 2276 master.cpp:438] Flags at startup: --acls=""
> --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
> --allocation_interval="1secs" -
> -allocator="HierarchicalDRF" --authenticate_agents="true"
> --authenticate_frameworks="true" --authenticate_http_frameworks="true"
> --authenticate_http_readonly="true" --au
> thenticate_http_readwrite="true" --authenticators="crammd5"
> --authorizers="local" --credentials="/tmp/V0UvSM/credentials"
> --framework_sorter="drf" --help="false" --hostn
> ame_lookup="true" --http_authenticators="basic"
> --http_framework_authenticators="basic" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0"
> --logging_level="INFO" --max_agent_ping_timeouts="5"
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="in_memory"
> --registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
> --registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
> --registry_store_timeout="100secs" --registry_strict="false"
> --root_submissions="true" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-1.3.1/_inst/share/mesos/webui"
> --work_dir="/tmp/V0UvSM/master" --zk_session_timeout="10secs"
> I0629 05:23:17.370513 2276 master.cpp:488] Master only allowing
> authenticated frameworks to register
> I0629 05:23:17.370525 2276 master.cpp:502] Master only allowing
> authenticated agents to register
> I0629 05:23:17.370534 2276 master.cpp:515] Master only allowing
> authenticated HTTP frameworks to register
> I0629 05:23:17.370543 2276 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/V0UvSM/credentials'
> I0629 05:23:17.370806 2276 master.cpp:560] Using default 'crammd5'
> authenticator
> I0629 05:23:17.370929 2276 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readonly'
> I0629 05:23:17.371073 2276 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readwrite'
> I0629 05:23:17.371193 2276 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-scheduler'
> I0629 05:23:17.371318 2276 master.cpp:640] Authorization enabled
> I0629 05:23:17.371455 2272 hierarchical.cpp:158] Initialized hierarchical
> allocator process
> I0629 05:23:17.371477 2290 whitelist_watcher.cpp:77] No whitelist given
> I0629 05:23:17.373731 2277 master.cpp:2161] Elected as the leading master!
> I0629 05:23:17.373760 2277 master.cpp:1700] Recovering from registrar
> I0629 05:23:17.373891 2280 registrar.cpp:345] Recovering registrar
> I0629 05:23:17.374527 2280 registrar.cpp:389] Successfully fetched the
> registry (0B) in 593152ns
> I0629 05:23:17.374625 2280 registrar.cpp:493] Applied 1 operations in
> 19216ns; attempting to update the registry
> I0629 05:23:17.375228 2280 registrar.cpp:550] Successfully updated the
> registry in 555008ns
> I0629 05:23:17.375336 2280 registrar.cpp:422] Successfully recovered
> registrar
> I0629 05:23:17.375826 2282 hierarchical.cpp:185] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0629 05:23:17.375850 2290 master.cpp:1799] Recovered 0 agents from the
> registry (129B); allowing 10mins for agents to re-register
> I0629 05:23:17.380674 2252 containerizer.cpp:221] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> W0629 05:23:17.381237 2252 backend.cpp:76] Failed to create 'aufs' backend:
> AufsBackend requires root privileges
> W0629 05:23:17.381350 2252 backend.cpp:76] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0629 05:23:17.381384 2252 provisioner.cpp:249] Using default backend 'copy'
> I0629 05:23:17.383884 2252 cluster.cpp:448] Creating default 'local'
> authorizer
> I0629 05:23:17.385763 2281 slave.cpp:231] Mesos agent started on
> (287)@172.17.0.3:42034
> I0629 05:23:17.385787 2281 slave.cpp:232] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_executors="true"
> --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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/mesos/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/is:
> olators/docker/volume" --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_reregistration_timeout="2secs"
> --executor_secret_key="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/executor_secret_key"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/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/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials"
> --http_heartbeat_interval="30secs" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem" --launcher="posix"
> --launcher_dir="/mesos/mesos-1.3.1/_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:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true"
> --runtime_dir="/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i"
> --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/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx"
> I0629 05:23:17.386165 2281 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/credential'
> I0629 05:23:17.386319 2281 slave.cpp:264] Agent using credential for:
> test-principal
> I0629 05:23:17.386339 2281 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_f1Jc3i/http_credentials'
> I0629 05:23:17.386600 2281 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-executor'
> I0629 05:23:17.386703 2281 http.cpp:996] Creating default 'jwt' HTTP
> authenticator for realm 'mesos-agent-executor'
> I0629 05:23:17.386885 2281 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readonly'
> I0629 05:23:17.386973 2281 http.cpp:996] Creating default 'jwt' HTTP
> authenticator for realm 'mesos-agent-readonly'
> I0629 05:23:17.387302 2281 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readwrite'
> I0629 05:23:17.387409 2281 http.cpp:996] Creating default 'jwt' HTTP
> authenticator for realm 'mesos-agent-readwrite'
> I0629 05:23:17.388684 2281 slave.cpp:531] Agent resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0629 05:23:17.388783 2281 slave.cpp:539] Agent attributes: [ ]
> I0629 05:23:17.388801 2281 slave.cpp:544] Agent hostname: b3c104d65da7
> I0629 05:23:17.388916 2294 status_update_manager.cpp:177] Pausing sending
> status updates
> I0629 05:23:17.390480 2288 state.cpp:62] Recovering state from
> '/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta'
> I0629 05:23:17.390751 2275 status_update_manager.cpp:203] Recovering status
> update manager
> I0629 05:23:17.391083 2286 containerizer.cpp:608] Recovering containerizer
> I0629 05:23:17.392966 2285 provisioner.cpp:410] Provisioner recovery complete
> I0629 05:23:17.393373 2272 slave.cpp:6075] Finished recovery
> I0629 05:23:17.393777 2272 slave.cpp:6257] Querying resource estimator for
> oversubscribable resources
> I0629 05:23:17.394049 2284 status_update_manager.cpp:177] Pausing sending
> status updates
> I0629 05:23:17.394065 2272 slave.cpp:924] New master detected at
> master@172.17.0.3:42034
> I0629 05:23:17.394129 2272 slave.cpp:959] Detecting new master
> I0629 05:23:17.394268 2272 slave.cpp:6271] Received oversubscribable
> resources {} from the resource estimator
> I0629 05:23:17.399830 2292 slave.cpp:986] Authenticating with master
> master@172.17.0.3:42034
> I0629 05:23:17.399900 2292 slave.cpp:997] Using default CRAM-MD5
> authenticatee
> I0629 05:23:17.400095 2289 authenticatee.cpp:121] Creating new client SASL
> connection
> I0629 05:23:17.400344 2275 master.cpp:7475] Authenticating
> slave(287)@172.17.0.3:42034
> I0629 05:23:17.400452 2282 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(624)@172.17.0.3:42034
> I0629 05:23:17.400650 2271 authenticator.cpp:98] Creating new server SASL
> connection
> I0629 05:23:17.400858 2294 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0629 05:23:17.400883 2294 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0629 05:23:17.400981 2291 authenticator.cpp:204] Received SASL
> authentication start
> I0629 05:23:17.401043 2291 authenticator.cpp:326] Authentication requires
> more steps
> I0629 05:23:17.401151 2293 authenticatee.cpp:259] Received SASL
> authentication step
> I0629 05:23:17.401382 2283 authenticator.cpp:232] Received SASL
> authentication step
> I0629 05:23:17.401419 2283 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0629 05:23:17.401434 2283 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0629 05:23:17.401470 2283 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0629 05:23:17.401492 2283 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0629 05:23:17.401506 2283 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 05:23:17.401515 2283 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 05:23:17.401532 2283 authenticator.cpp:318] Authentication success
> I0629 05:23:17.401620 2289 authenticatee.cpp:299] Authentication success
> I0629 05:23:17.401682 2281 master.cpp:7505] Successfully authenticated
> principal 'test-principal' at slave(287)@172.17.0.3:42034
> I0629 05:23:17.401913 2273 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(624)@172.17.0.3:42034
> I0629 05:23:17.401921 2284 slave.cpp:1081] Successfully authenticated with
> master master@172.17.0.3:42034
> I0629 05:23:17.402212 2284 slave.cpp:1509] Will retry registration in
> 1.256299ms if necessary
> I0629 05:23:17.402345 2294 master.cpp:5429] Received register agent message
> from slave(287)@172.17.0.3:42034 (b3c104d65da7)
> I0629 05:23:17.402477 2294 master.cpp:3659] Authorizing agent with principal
> 'test-principal'
> I0629 05:23:17.402930 2271 master.cpp:5564] Registering agent at
> slave(287)@172.17.0.3:42034 (b3c104d65da7) with id
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
> I0629 05:23:17.403379 2281 registrar.cpp:493] Applied 1 operations in
> 62566ns; attempting to update the registry
> I0629 05:23:17.404207 2281 registrar.cpp:550] Successfully updated the
> registry in 769024ns
> I0629 05:23:17.404608 2286 slave.cpp:1509] Will retry registration in
> 25.850396ms if necessary
> I0629 05:23:17.405179 2276 slave.cpp:4794] Received ping from
> slave-observer(289)@172.17.0.3:42034
> I0629 05:23:17.405144 2294 master.cpp:5639] Registered agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0629 05:23:17.405441 2276 slave.cpp:1127] Registered with master
> master@172.17.0.3:42034; given agent ID
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
> I0629 05:23:17.405465 2276 fetcher.cpp:94] Clearing fetcher cache
> I0629 05:23:17.405508 2293 hierarchical.cpp:525] Added agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 (b3c104d65da7) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
> I0629 05:23:17.405594 2294 master.cpp:5429] Received register agent message
> from slave(287)@172.17.0.3:42034 (b3c104d65da7)
> I0629 05:23:17.405743 2294 master.cpp:3659] Authorizing agent with principal
> 'test-principal'
> I0629 05:23:17.405750 2288 status_update_manager.cpp:184] Resuming sending
> status updates
> I0629 05:23:17.405933 2293 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:17.405971 2276 slave.cpp:1155] Checkpointing SlaveInfo to
> '/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
> I0629 05:23:17.405989 2293 hierarchical.cpp:1434] Performed allocation for 1
> agents in 192285ns
> I0629 05:23:17.406347 2276 slave.cpp:1193] Forwarding total oversubscribed
> resources {}
> I0629 05:23:17.406415 2271 master.cpp:5542] Agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7) already registered, resending acknowledgement
> I0629 05:23:17.406491 2276 slave.cpp:924] New master detected at
> master@172.17.0.3:42034
> I0629 05:23:17.406496 2280 status_update_manager.cpp:177] Pausing sending
> status updates
> I0629 05:23:17.406548 2276 slave.cpp:959] Detecting new master
> I0629 05:23:17.406570 2271 master.cpp:6324] Received update of agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7) with total oversubscribed resources {}
> I0629 05:23:17.406694 2276 slave.cpp:1127] Registered with master
> master@172.17.0.3:42034; given agent ID
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
> I0629 05:23:17.406720 2276 fetcher.cpp:94] Clearing fetcher cache
> I0629 05:23:17.406842 2275 status_update_manager.cpp:184] Resuming sending
> status updates
> I0629 05:23:17.406961 2276 slave.cpp:1155] Checkpointing SlaveInfo to
> '/tmp/RegisterSlaveValidationTest_DropInvalidReregistration_RVRQXx/meta/slaves/25091bef-3845-4bb6-ae23-e18ac0f4d174-S0/slave.info'
> I0629 05:23:17.407268 2276 slave.cpp:1193] Forwarding total oversubscribed
> resources {}
> I0629 05:23:17.407431 2278 master.cpp:6324] Received update of agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7) with total oversubscribed resources {}
> I0629 05:23:17.413727 2276 slave.cpp:986] Authenticating with master
> master@172.17.0.3:42034
> I0629 05:23:17.413785 2276 slave.cpp:997] Using default CRAM-MD5
> authenticatee
> I0629 05:23:17.413978 2278 authenticatee.cpp:121] Creating new client SASL
> connection
> I0629 05:23:17.414268 2290 master.cpp:7475] Authenticating
> slave(287)@172.17.0.3:42034
> I0629 05:23:17.414409 2273 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(625)@172.17.0.3:42034
> I0629 05:23:17.414752 2292 authenticator.cpp:98] Creating new server SASL
> connection
> I0629 05:23:17.414988 2272 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0629 05:23:17.415014 2272 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0629 05:23:17.415158 2278 authenticator.cpp:204] Received SASL
> authentication start
> I0629 05:23:17.415225 2278 authenticator.cpp:326] Authentication requires
> more steps
> I0629 05:23:17.415345 2285 authenticatee.cpp:259] Received SASL
> authentication step
> I0629 05:23:17.415586 2271 authenticator.cpp:232] Received SASL
> authentication step
> I0629 05:23:17.415616 2271 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0629 05:23:17.415629 2271 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0629 05:23:17.415665 2271 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0629 05:23:17.415689 2271 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'b3c104d65da7' server FQDN: 'b3c104d65da7'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0629 05:23:17.415701 2271 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 05:23:17.415711 2271 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 05:23:17.415726 2271 authenticator.cpp:318] Authentication success
> I0629 05:23:17.415807 2278 authenticatee.cpp:299] Authentication success
> I0629 05:23:17.415865 2294 master.cpp:7505] Successfully authenticated
> principal 'test-principal' at slave(287)@172.17.0.3:42034
> I0629 05:23:17.415910 2288 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(625)@172.17.0.3:42034
> I0629 05:23:17.416126 2274 slave.cpp:1081] Successfully authenticated with
> master master@172.17.0.3:42034
> I0629 05:23:18.372947 2275 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:18.373133 2275 hierarchical.cpp:1434] Performed allocation for 1
> agents in 578948ns
> I0629 05:23:19.374871 2289 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:19.375056 2289 hierarchical.cpp:1434] Performed allocation for 1
> agents in 520444ns
> I0629 05:23:20.375833 2290 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:20.375975 2290 hierarchical.cpp:1434] Performed allocation for 1
> agents in 435113ns
> I0629 05:23:21.377182 2279 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:21.377399 2279 hierarchical.cpp:1434] Performed allocation for 1
> agents in 639655ns
> I0629 05:23:22.378278 2277 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:22.378437 2277 hierarchical.cpp:1434] Performed allocation for 1
> agents in 427151ns
> I0629 05:23:23.380287 2292 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:23.380481 2292 hierarchical.cpp:1434] Performed allocation for 1
> agents in 578747ns
> I0629 05:23:24.381932 2273 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:24.382097 2273 hierarchical.cpp:1434] Performed allocation for 1
> agents in 476981ns
> I0629 05:23:25.383314 2275 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:25.383499 2275 hierarchical.cpp:1434] Performed allocation for 1
> agents in 500084ns
> I0629 05:23:26.384625 2281 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:26.384855 2281 hierarchical.cpp:1434] Performed allocation for 1
> agents in 515354ns
> I0629 05:23:27.385927 2291 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:27.386139 2291 hierarchical.cpp:1434] Performed allocation for 1
> agents in 562796ns
> I0629 05:23:28.387132 2285 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:28.387297 2285 hierarchical.cpp:1434] Performed allocation for 1
> agents in 438370ns
> I0629 05:23:29.388170 2286 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:29.388309 2286 hierarchical.cpp:1434] Performed allocation for 1
> agents in 317943ns
> I0629 05:23:30.389729 2278 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:30.389909 2278 hierarchical.cpp:1434] Performed allocation for 1
> agents in 475524ns
> I0629 05:23:31.390977 2280 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:31.391084 2280 hierarchical.cpp:1434] Performed allocation for 1
> agents in 266216ns
> I0629 05:23:32.391724 2287 hierarchical.cpp:1850] No allocations performed
> I0629 05:23:32.391827 2287 hierarchical.cpp:1434] Performed allocation for 1
> agents in 270448ns
> I0629 05:23:32.394664 2276 slave.cpp:6257] Querying resource estimator for
> oversubscribable resources
> I0629 05:23:32.395167 2293 slave.cpp:6271] Received oversubscribable
> resources {} from the resource estimator
> I0629 05:23:32.406095 2288 slave.cpp:4794] Received ping from
> slave-observer(289)@172.17.0.3:42034
> ../../src/tests/master_validation_tests.cpp:3757: Failure
> Failed to wait 15secs for reregisterSlaveMessage
> I0629 05:23:32.409525 2291 slave.cpp:796] Agent terminating
> I0629 05:23:32.410306 2292 master.cpp:1313] Agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7) disconnected
> I0629 05:23:32.410360 2292 master.cpp:3197] Disconnecting agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7)
> I0629 05:23:32.410907 2292 master.cpp:3216] Deactivating agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 at slave(287)@172.17.0.3:42034
> (b3c104d65da7)
> I0629 05:23:32.411128 2288 hierarchical.cpp:653] Agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0 deactivated
> I0629 05:23:32.418536 2278 master.cpp:1155] Master terminating
> I0629 05:23:32.419867 2289 hierarchical.cpp:558] Removed agent
> 25091bef-3845-4bb6-ae23-e18ac0f4d174-S0
> ../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock,
> filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <58-BF 04-20 F5-7F 00-00>,
> 1, 1-byte object <E8>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] RegisterSlaveValidationTest.DropInvalidReregistration (15061 ms)
> {code}
> Observed on macOS when testing 1.3.1:
> {noformat}
> [ RUN ] RegisterSlaveValidationTest.DropInvalidReregistration
> I0802 13:34:21.685421 2516382656 cluster.cpp:162] Creating default 'local'
> authorizer
> I0802 13:34:21.686971 224620544 master.cpp:436] Master
> 21402191-4b94-4a3c-9c84-cf9942b0b81a (192.168.1.15) started on
> 192.168.1.15:53913
> I0802 13:34:21.686991 224620544 master.cpp:438] Flags at startup: --acls=""
> --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate_agents="true" --authenticate_frameworks="true"
> --authenticate_http_frameworks="true" --authenticate_http_readonly="true"
> --authenticate_http_readwrite="true" --authenticators="crammd5"
> --authorizers="local"
> --credentials="/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/credentials"
> --framework_sorter="drf" --help="false" --hostname_lookup="true"
> --http_authenticators="basic" --http_framework_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="in_memory"
> --registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
> --registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
> --registry_store_timeout="100secs" --registry_strict="false"
> --root_submissions="true" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui"
> --work_dir="/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/master"
> --zk_session_timeout="10secs"
> I0802 13:34:21.687160 224620544 master.cpp:488] Master only allowing
> authenticated frameworks to register
> I0802 13:34:21.687182 224620544 master.cpp:502] Master only allowing
> authenticated agents to register
> I0802 13:34:21.687191 224620544 master.cpp:515] Master only allowing
> authenticated HTTP frameworks to register
> I0802 13:34:21.687198 224620544 credentials.hpp:37] Loading credentials for
> authentication from
> '/private/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/7eFkbc/credentials'
> I0802 13:34:21.687373 224620544 master.cpp:560] Using default 'crammd5'
> authenticator
> I0802 13:34:21.687434 224620544 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readonly'
> I0802 13:34:21.687558 224620544 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readwrite'
> I0802 13:34:21.687672 224620544 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-scheduler'
> I0802 13:34:21.687784 224620544 master.cpp:640] Authorization enabled
> I0802 13:34:21.689018 227303424 master.cpp:2161] Elected as the leading
> master!
> I0802 13:34:21.689031 227303424 master.cpp:1700] Recovering from registrar
> I0802 13:34:21.689425 224083968 registrar.cpp:389] Successfully fetched the
> registry (0B) in 326912ns
> I0802 13:34:21.689481 224083968 registrar.cpp:493] Applied 1 operations in
> 17us; attempting to update the registry
> I0802 13:34:21.689767 224083968 registrar.cpp:550] Successfully updated the
> registry in 263168ns
> I0802 13:34:21.689812 224083968 registrar.cpp:422] Successfully recovered
> registrar
> I0802 13:34:21.690094 226766848 master.cpp:1799] Recovered 0 agents from the
> registry (135B); allowing 10mins for agents to re-register
> I0802 13:34:21.692261 2516382656 containerizer.cpp:221] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0802 13:34:21.692390 2516382656 provisioner.cpp:249] Using default backend
> 'copy'
> I0802 13:34:21.693034 2516382656 cluster.cpp:448] Creating default 'local'
> authorizer
> I0802 13:34:21.693660 226766848 slave.cpp:231] Mesos agent started on
> (5)@192.168.1.15:53913
> I0802 13:34:21.693699 226766848 slave.cpp:232] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/mesos/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/mesos/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/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/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/http_credentials"
> --http_heartbeat_interval="30secs" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem" --launcher="posix"
> --launcher_dir="/Users/bmahler/Downloads/mesos-1.3.1/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:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --runtime_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true"
> --switch_user="true" --version="false"
> --work_dir="/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_JdMGIN"
> I0802 13:34:21.693886 226766848 credentials.hpp:86] Loading credential for
> authentication from
> '/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/credential'
> I0802 13:34:21.693975 226766848 slave.cpp:264] Agent using credential for:
> test-principal
> I0802 13:34:21.693989 226766848 credentials.hpp:37] Loading credentials for
> authentication from
> '/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_FaKGv2/http_credentials'
> I0802 13:34:21.694102 226766848 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readonly'
> I0802 13:34:21.694186 226766848 http.cpp:975] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readwrite'
> I0802 13:34:21.694964 226766848 slave.cpp:531] Agent resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0802 13:34:21.695008 226766848 slave.cpp:539] Agent attributes: [ ]
> I0802 13:34:21.695016 226766848 slave.cpp:544] Agent hostname: 192.168.1.15
> I0802 13:34:21.695087 227840000 status_update_manager.cpp:177] Pausing
> sending status updates
> I0802 13:34:21.695673 225693696 state.cpp:62] Recovering state from
> '/var/folders/xb/nkj68dnn2wqd8mgfb_mvsds00000gn/T/RegisterSlaveValidationTest_DropInvalidReregistration_JdMGIN/meta'
> I0802 13:34:21.695814 226230272 status_update_manager.cpp:203] Recovering
> status update manager
> I0802 13:34:21.695937 225693696 containerizer.cpp:608] Recovering
> containerizer
> I0802 13:34:21.696552 224620544 provisioner.cpp:410] Provisioner recovery
> complete
> I0802 13:34:21.696770 226766848 slave.cpp:6075] Finished recovery
> I0802 13:34:21.697232 225157120 status_update_manager.cpp:177] Pausing
> sending status updates
> I0802 13:34:21.697247 226766848 slave.cpp:924] New master detected at
> master@192.168.1.15:53913
> I0802 13:34:21.697314 226766848 slave.cpp:959] Detecting new master
> I0802 13:34:21.706558 227303424 slave.cpp:986] Authenticating with master
> master@192.168.1.15:53913
> I0802 13:34:21.706626 227303424 slave.cpp:997] Using default CRAM-MD5
> authenticatee
> I0802 13:34:21.706876 227840000 authenticatee.cpp:121] Creating new client
> SASL connection
> I0802 13:34:21.707221 227303424 master.cpp:7475] Authenticating
> slave(5)@192.168.1.15:53913
> I0802 13:34:21.707667 224083968 authenticator.cpp:98] Creating new server
> SASL connection
> I0802 13:34:21.707852 227840000 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0802 13:34:21.707921 227840000 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0802 13:34:21.708161 227840000 authenticator.cpp:204] Received SASL
> authentication start
> I0802 13:34:21.708250 227840000 authenticator.cpp:326] Authentication
> requires more steps
> I0802 13:34:21.708449 225693696 authenticatee.cpp:259] Received SASL
> authentication step
> I0802 13:34:21.708734 227303424 authenticator.cpp:232] Received SASL
> authentication step
> I0802 13:34:21.708827 227303424 authenticator.cpp:318] Authentication success
> I0802 13:34:21.708992 225693696 authenticatee.cpp:299] Authentication success
> I0802 13:34:21.709059 224083968 master.cpp:7505] Successfully authenticated
> principal 'test-principal' at slave(5)@192.168.1.15:53913
> I0802 13:34:21.709574 226766848 slave.cpp:1081] Successfully authenticated
> with master master@192.168.1.15:53913
> I0802 13:34:21.709900 224083968 master.cpp:5429] Received register agent
> message from slave(5)@192.168.1.15:53913 (192.168.1.15)
> I0802 13:34:21.709947 224083968 master.cpp:3659] Authorizing agent with
> principal 'test-principal'
> I0802 13:34:21.710321 225693696 master.cpp:5564] Registering agent at
> slave(5)@192.168.1.15:53913 (192.168.1.15) with id
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0
> I0802 13:34:21.710543 224620544 registrar.cpp:493] Applied 1 operations in
> 47us; attempting to update the registry
> I0802 13:34:21.710937 224620544 registrar.cpp:550] Successfully updated the
> registry in 355840ns
> I0802 13:34:21.711361 225157120 master.cpp:5639] Registered agent
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
> (192.168.1.15) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0802 13:34:21.711501 224620544 hierarchical.cpp:525] Added agent
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 (192.168.1.15) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
> I0802 13:34:21.711558 227303424 slave.cpp:1127] Registered with master
> master@192.168.1.15:53913; given agent ID
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0
> I0802 13:34:21.711809 224620544 status_update_manager.cpp:184] Resuming
> sending status updates
> I0802 13:34:21.712311 227303424 slave.cpp:1193] Forwarding total
> oversubscribed resources {}
> I0802 13:34:21.712429 224083968 master.cpp:6324] Received update of agent
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
> (192.168.1.15) with total oversubscribed resources {}
> I0802 13:34:21.712707 226766848 slave.cpp:924] New master detected at
> master@192.168.1.15:53913
> I0802 13:34:21.712712 226230272 status_update_manager.cpp:177] Pausing
> sending status updates
> I0802 13:34:21.712759 226766848 slave.cpp:959] Detecting new master
> I0802 13:34:21.720463 224620544 slave.cpp:986] Authenticating with master
> master@192.168.1.15:53913
> I0802 13:34:21.720505 224620544 slave.cpp:997] Using default CRAM-MD5
> authenticatee
> I0802 13:34:21.720631 225693696 authenticatee.cpp:121] Creating new client
> SASL connection
> I0802 13:34:21.720824 226766848 master.cpp:7475] Authenticating
> slave(5)@192.168.1.15:53913
> I0802 13:34:21.721016 224620544 authenticator.cpp:98] Creating new server
> SASL connection
> I0802 13:34:21.721148 227840000 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0802 13:34:21.721169 227840000 authenticatee.cpp:239] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0802 13:34:21.721251 227840000 authenticator.cpp:204] Received SASL
> authentication start
> I0802 13:34:21.721302 227840000 authenticator.cpp:326] Authentication
> requires more steps
> I0802 13:34:21.721350 227840000 authenticatee.cpp:259] Received SASL
> authentication step
> I0802 13:34:21.721472 226766848 authenticator.cpp:232] Received SASL
> authentication step
> I0802 13:34:21.721508 226766848 authenticator.cpp:318] Authentication success
> I0802 13:34:21.721577 227303424 authenticatee.cpp:299] Authentication success
> I0802 13:34:21.721617 227840000 master.cpp:7505] Successfully authenticated
> principal 'test-principal' at slave(5)@192.168.1.15:53913
> I0802 13:34:21.721856 225157120 slave.cpp:1081] Successfully authenticated
> with master master@192.168.1.15:53913
> I0802 13:34:21.722730 227303424 master.cpp:5708] Received re-register agent
> message from agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
> slave(5)@192.168.1.15:53913 (192.168.1.15)
> I0802 13:34:21.722759 227303424 master.cpp:3659] Authorizing agent with
> principal 'test-principal'
> I0802 13:34:21.735528 227303424 master.cpp:5691] Ignoring re-register agent
> message from agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
> slave(5)@192.168.1.15:53913 (192.168.1.15) as re-registration is already in
> progress
> I0802 13:34:21.735604 227303424 master.cpp:5824] Re-registering agent
> 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at slave(5)@192.168.1.15:53913
> (192.168.1.15)
> I0802 13:34:21.735736 227303424 master.cpp:6233] Sending updated checkpointed
> resources {} to agent 21402191-4b94-4a3c-9c84-cf9942b0b81a-S0 at
> slave(5)@192.168.1.15:53913 (192.168.1.15)
> ../3rdparty/libprocess/include/process/gmock.hpp:601: Failure
> Mock function called more times than expected - returning default value.
> Function call: filter(@0x7f92ecd8eef0 16-byte object <B0-A8 07-11 01-00
> 00-00 90-C4 D8-EC 92-7F 00-00>)
> Returns: false
> Expected: to be never called
> Actual: called once - over-saturated and active
> *** Aborted at 1501706061 (unix time) try "date -d @1501706061" if you are
> using GNU date ***
> PC: @ 0x10a76f480 testing::UnitTest::AddTestPartResult()
> *** SIGSEGV (@0x0) received by PID 62261 (TID 0x70000d949000) stack trace: ***
> @ 0x7fff8d2c4b3a _sigtramp
> @ 0x17 (unknown)
> @ 0x10a76ec87 testing::internal::AssertHelper::operator=()
> @ 0x10a7c6ef7
> testing::internal::GoogleTestFailureReporter::ReportFailure()
> @ 0x1089ede65 testing::internal::Expect()
> @ 0x10a7badd5
> testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
> @ 0x1089f3458 testing::internal::FunctionMockerBase<>::InvokeWith()
> @ 0x1089f3403 testing::internal::FunctionMocker<>::Invoke()
> @ 0x1089ddb85 process::MockFilter::filter()
> @ 0x1089f3851 process::TestsFilter::handle<>()
> @ 0x1089dabfd process::TestsFilter::filter()
> @ 0x1105ea85f
> process::ProcessManager::resume()::FilterVisitor::visit()
> @ 0x10da9991e process::MessageEvent::visit()
> @ 0x110599e78 process::ProcessManager::resume()
> @ 0x1106759b0
> process::ProcessManager::init_threads()::$_1::operator()()
> @ 0x1106755d2
> _ZNSt3__114__thread_proxyINS_5tupleIJZN7process14ProcessManager12init_threadsEvE3$_1EEEEEPvS6_
> @ 0x7fff8d2ce93b _pthread_body
> @ 0x7fff8d2ce887 _pthread_start
> @ 0x7fff8d2ce08d thread_start
> [1] 62261 segmentation fault ./bin/mesos-tests.sh --gtest_repeat=-1
> --gtest_break_on_failure --verbose
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
