[ https://issues.apache.org/jira/browse/MESOS-7739?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexander Rukletsov reassigned MESOS-7739: ------------------------------------------ Assignee: (was: Neil Conway) > RegisterSlaveValidationTest.DropInvalidReregistration is flaky > -------------------------------------------------------------- > > Key: MESOS-7739 > URL: https://issues.apache.org/jira/browse/MESOS-7739 > Project: Mesos > Issue Type: Bug > Reporter: Vinod Kone > 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)