[ https://issues.apache.org/jira/browse/MESOS-8000?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16188086#comment-16188086 ]
Till Toenshoff commented on MESOS-8000: --------------------------------------- Observed on internal CI (Centos7): {noformat} 00:53:39 ../../src/tests/containerizer/cni_isolator_tests.cpp:1419: Failure 00:53:39 Failed to wait 15secs for subscribed {noformat} Log: {noformat} 00:53:24 [ RUN ] NetworkParam/DefaultExecutorCniTest.ROOT_VerifyContainerIP/0 00:53:24 I0930 00:53:24.468544 7413 cluster.cpp:162] Creating default 'local' authorizer 00:53:24 I0930 00:53:24.469557 26520 master.cpp:445] Master 473b9c2c-8d12-417d-98de-d71cd175d503 (ip-172-16-10-96.ec2.internal) started on 172.16.10.96:38662 00:53:24 I0930 00:53:24.469573 26520 master.cpp:447] 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="/tmp/g7H2KI/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/g7H2KI/master" --zk_session_timeout="10secs" 00:53:24 I0930 00:53:24.469699 26520 master.cpp:497] Master only allowing authenticated frameworks to register 00:53:24 I0930 00:53:24.469707 26520 master.cpp:511] Master only allowing authenticated agents to register 00:53:24 I0930 00:53:24.469712 26520 master.cpp:524] Master only allowing authenticated HTTP frameworks to register 00:53:24 I0930 00:53:24.469717 26520 credentials.hpp:37] Loading credentials for authentication from '/tmp/g7H2KI/credentials' 00:53:24 I0930 00:53:24.469817 26520 master.cpp:569] Using default 'crammd5' authenticator 00:53:24 I0930 00:53:24.469864 26520 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 00:53:24 I0930 00:53:24.469899 26520 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 00:53:24 I0930 00:53:24.469923 26520 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 00:53:24 I0930 00:53:24.469943 26520 master.cpp:649] Authorization enabled 00:53:24 I0930 00:53:24.470126 26523 hierarchical.cpp:171] Initialized hierarchical allocator process 00:53:24 I0930 00:53:24.470139 26519 whitelist_watcher.cpp:77] No whitelist given 00:53:24 I0930 00:53:24.470667 26520 master.cpp:2216] Elected as the leading master! 00:53:24 I0930 00:53:24.470679 26520 master.cpp:1705] Recovering from registrar 00:53:24 I0930 00:53:24.470717 26521 registrar.cpp:347] Recovering registrar 00:53:24 I0930 00:53:24.470865 26521 registrar.cpp:391] Successfully fetched the registry (0B) in 130048ns 00:53:24 I0930 00:53:24.470899 26521 registrar.cpp:495] Applied 1 operations in 6443ns; attempting to update the registry 00:53:24 I0930 00:53:24.471029 26518 registrar.cpp:552] Successfully updated the registry in 113920ns 00:53:24 I0930 00:53:24.471076 26518 registrar.cpp:424] Successfully recovered registrar 00:53:24 I0930 00:53:24.471153 26519 master.cpp:1809] Recovered 0 agents from the registry (168B); allowing 10mins for agents to re-register 00:53:24 I0930 00:53:24.471210 26519 hierarchical.cpp:209] Skipping recovery of hierarchical allocator: nothing to recover 00:53:24 W0930 00:53:24.473450 7413 process.cpp:3194] Attempted to spawn already running process files@172.16.10.96:38662 00:53:24 I0930 00:53:24.473793 7413 containerizer.cpp:292] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 00:53:24 I0930 00:53:24.479225 7413 linux_launcher.cpp:146] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher 00:53:24 I0930 00:53:24.479602 7413 provisioner.cpp:255] Using default backend 'overlay' 00:53:24 I0930 00:53:24.480844 7413 cluster.cpp:448] Creating default 'local' authorizer 00:53:24 I0930 00:53:24.481324 26523 slave.cpp:254] Mesos agent started on (1065)@172.16.10.96:38662 00:53:24 I0930 00:53:24.481353 26523 slave.cpp:255] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/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/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="linux" --launcher_dir="/home/centos/workspace/mesos/Mesos_CI-build/FLAG/Plain/label/mesos-ec2-centos-7/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --network_cni_config_dir="/tmp/g7H2KI/configs" --network_cni_plugins_dir="/tmp/g7H2KI/plugins" --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/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49" --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/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_3hqPpr" --zk_session_timeout="10secs" 00:53:24 I0930 00:53:24.481528 26523 credentials.hpp:86] Loading credential for authentication from '/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/credential' 00:53:24 I0930 00:53:24.481555 7413 scheduler.cpp:184] Version: 1.5.0 00:53:24 I0930 00:53:24.481590 26523 slave.cpp:287] Agent using credential for: test-principal 00:53:24 I0930 00:53:24.481600 26523 credentials.hpp:37] Loading credentials for authentication from '/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_2VJC49/http_credentials' 00:53:24 I0930 00:53:24.481818 26523 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 00:53:24 I0930 00:53:24.482049 26518 scheduler.cpp:470] New master detected at master@172.16.10.96:38662 00:53:24 I0930 00:53:24.482069 26518 scheduler.cpp:479] Waiting for 0ns before initiating a re-(connection) attempt with the master 00:53:24 I0930 00:53:24.482447 26523 slave.cpp:585] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 00:53:24 I0930 00:53:24.482517 26523 slave.cpp:593] Agent attributes: [ ] 00:53:24 I0930 00:53:24.482524 26523 slave.cpp:602] Agent hostname: ip-172-16-10-96.ec2.internal 00:53:24 I0930 00:53:24.482759 26523 status_update_manager.cpp:177] Pausing sending status updates 00:53:24 I0930 00:53:24.482784 26523 state.cpp:64] Recovering state from '/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_3hqPpr/meta' 00:53:24 I0930 00:53:24.483317 26522 scheduler.cpp:361] Connected with the master at http://172.16.10.96:38662/master/api/v1/scheduler 00:53:24 I0930 00:53:24.483460 26522 scheduler.cpp:243] Sending SUBSCRIBE call to http://172.16.10.96:38662/master/api/v1/scheduler 00:53:24 I0930 00:53:24.483510 26519 status_update_manager.cpp:203] Recovering status update manager 00:53:24 I0930 00:53:24.483548 26519 containerizer.cpp:648] Recovering containerizer 00:53:24 I0930 00:53:24.483911 26517 process.cpp:3929] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler' 00:53:24 I0930 00:53:24.484201 26517 http.cpp:1185] HTTP POST for /master/api/v1/scheduler from 172.16.10.96:46828 00:53:24 I0930 00:53:24.484278 26517 master.cpp:2598] Received subscription request for HTTP framework 'default' 00:53:24 I0930 00:53:24.484302 26517 master.cpp:2281] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 00:53:24 I0930 00:53:24.484457 26517 master.cpp:2734] Subscribing framework 'default' with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 00:53:24 I0930 00:53:24.484597 26522 hierarchical.cpp:303] Added framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:24 I0930 00:53:24.484633 26522 hierarchical.cpp:1943] No allocations performed 00:53:24 I0930 00:53:24.484642 26522 hierarchical.cpp:2033] No inverse offers to send out! 00:53:24 I0930 00:53:24.484650 26522 hierarchical.cpp:1486] Performed allocation for 0 agents in 21322ns 00:53:24 I0930 00:53:24.484728 26522 master.hpp:349] Sending heartbeat to framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:24 I0930 00:53:24.484959 26522 provisioner.cpp:416] Provisioner recovery complete 00:53:24 I0930 00:53:24.485083 26519 slave.cpp:6313] Finished recovery 00:53:24 I0930 00:53:24.485141 26522 scheduler.cpp:676] Enqueuing event SUBSCRIBED received from http://172.16.10.96:38662/master/api/v1/scheduler 00:53:24 00:53:24 GMOCK WARNING: 00:53:24 Uninteresting mock function call - returning directly. 00:53:24 Function call: subscribed(0x7fff74866cc0, @0x7f1df8049d10 48-byte object <D0-76 F1-25 1E-7F 00-00 00-00 00-00 00-00 00-00 07-00 00-00 00-00 00-00 60-80 09-F8 1D-7F 00-00 A0-AE 03-F8 1D-7F 00-00 00-00 00-00 00-00 2E-40>) 00:53:24 NOTE: You can safely ignore the above warning unless this call should not happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't mean to enforce the call. See https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect for details. 00:53:24 I0930 00:53:24.485328 26519 slave.cpp:6495] Querying resource estimator for oversubscribable resources 00:53:24 I0930 00:53:24.485380 26518 status_update_manager.cpp:177] Pausing sending status updates 00:53:24 I0930 00:53:24.485383 26519 slave.cpp:993] New master detected at master@172.16.10.96:38662 00:53:24 I0930 00:53:24.485405 26519 slave.cpp:1028] Detecting new master 00:53:24 I0930 00:53:24.485437 26519 slave.cpp:6509] Received oversubscribable resources {} from the resource estimator 00:53:24 I0930 00:53:24.485512 26516 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.16.10.96:38662/master/api/v1/scheduler 00:53:24 00:53:24 GMOCK WARNING: 00:53:24 Uninteresting mock function call - returning directly. 00:53:24 Function call: heartbeat(0x7fff74866cc0) 00:53:24 NOTE: You can safely ignore the above warning unless this call should not happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't mean to enforce the call. See https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect for details. 00:53:24 I0930 00:53:24.494861 26518 slave.cpp:1055] Authenticating with master master@172.16.10.96:38662 00:53:24 I0930 00:53:24.494886 26518 slave.cpp:1066] Using default CRAM-MD5 authenticatee 00:53:24 I0930 00:53:24.494951 26518 authenticatee.cpp:121] Creating new client SASL connection 00:53:24 I0930 00:53:24.495404 26518 master.cpp:7915] Authenticating slave(1065)@172.16.10.96:38662 00:53:24 I0930 00:53:24.495450 26518 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1906)@172.16.10.96:38662 00:53:24 I0930 00:53:24.495517 26518 authenticator.cpp:98] Creating new server SASL connection 00:53:24 I0930 00:53:24.495895 26518 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 00:53:24 I0930 00:53:24.495914 26518 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 00:53:24 I0930 00:53:24.495942 26518 authenticator.cpp:204] Received SASL authentication start 00:53:24 I0930 00:53:24.495975 26518 authenticator.cpp:326] Authentication requires more steps 00:53:24 I0930 00:53:24.496012 26518 authenticatee.cpp:259] Received SASL authentication step 00:53:24 I0930 00:53:24.496073 26518 authenticator.cpp:232] Received SASL authentication step 00:53:24 I0930 00:53:24.496093 26518 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 00:53:24 I0930 00:53:24.496100 26518 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 00:53:24 I0930 00:53:24.496109 26518 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 00:53:24 I0930 00:53:24.496124 26518 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 00:53:24 I0930 00:53:24.496131 26518 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 00:53:24 I0930 00:53:24.496136 26518 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 00:53:24 I0930 00:53:24.496148 26518 authenticator.cpp:318] Authentication success 00:53:24 I0930 00:53:24.496187 26518 authenticatee.cpp:299] Authentication success 00:53:24 I0930 00:53:24.496219 26518 master.cpp:7945] Successfully authenticated principal 'test-principal' at slave(1065)@172.16.10.96:38662 00:53:24 I0930 00:53:24.496245 26518 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1906)@172.16.10.96:38662 00:53:24 I0930 00:53:24.496309 26518 slave.cpp:1150] Successfully authenticated with master master@172.16.10.96:38662 00:53:24 I0930 00:53:24.496371 26518 slave.cpp:1629] Will retry registration in 19.330062ms if necessary 00:53:24 I0930 00:53:24.496448 26520 master.cpp:5819] Received register agent message from slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 00:53:24 I0930 00:53:24.496477 26520 master.cpp:3856] Authorizing agent with principal 'test-principal' 00:53:24 I0930 00:53:24.496562 26518 master.cpp:5879] Authorized registration of agent at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 00:53:24 I0930 00:53:24.496608 26518 master.cpp:5972] Registering agent at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) with id 473b9c2c-8d12-417d-98de-d71cd175d503-S0 00:53:24 I0930 00:53:24.496718 26518 registrar.cpp:495] Applied 1 operations in 11171ns; attempting to update the registry 00:53:24 I0930 00:53:24.496876 26517 registrar.cpp:552] Successfully updated the registry in 135936ns 00:53:24 I0930 00:53:24.496932 26520 master.cpp:6019] Admitted agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 00:53:24 I0930 00:53:24.497076 26516 slave.cpp:4969] Received ping from slave-observer(959)@172.16.10.96:38662 00:53:24 I0930 00:53:24.497117 26516 slave.cpp:1196] Registered with master master@172.16.10.96:38662; given agent ID 473b9c2c-8d12-417d-98de-d71cd175d503-S0 00:53:24 I0930 00:53:24.497076 26520 master.cpp:6050] Registered agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) with [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 00:53:24 I0930 00:53:24.497218 26520 hierarchical.cpp:593] Added agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 (ip-172-16-10-96.ec2.internal) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 00:53:24 I0930 00:53:24.497334 26516 slave.cpp:1216] Checkpointing SlaveInfo to '/tmp/NetworkParam_DefaultExecutorCniTest_ROOT_VerifyContainerIP_0_3hqPpr/meta/slaves/473b9c2c-8d12-417d-98de-d71cd175d503-S0/slave.info' 00:53:24 I0930 00:53:24.497414 26520 hierarchical.cpp:2033] No inverse offers to send out! 00:53:24 I0930 00:53:24.497431 26520 hierarchical.cpp:1486] Performed allocation for 1 agents in 166064ns 00:53:24 I0930 00:53:24.497460 26520 status_update_manager.cpp:184] Resuming sending status updates 00:53:24 I0930 00:53:24.497498 26516 slave.cpp:1265] Forwarding total oversubscribed resources {} 00:53:24 I0930 00:53:24.497576 26520 master.cpp:7745] Sending 1 offers to framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 00:53:25 I0930 00:53:24.497761 26520 master.cpp:6814] Received update of agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) with total oversubscribed resources {} 00:53:25 I0930 00:53:24.497841 26520 hierarchical.cpp:660] Agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 (ip-172-16-10-96.ec2.internal) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] 00:53:25 I0930 00:53:24.498191 26521 scheduler.cpp:676] Enqueuing event OFFERS received from http://172.16.10.96:38662/master/api/v1/scheduler 00:53:26 I0930 00:53:25.470976 26518 hierarchical.cpp:1943] No allocations performed 00:53:26 I0930 00:53:25.471012 26518 hierarchical.cpp:2033] No inverse offers to send out! 00:53:26 I0930 00:53:25.471022 26518 hierarchical.cpp:1486] Performed allocation for 1 agents in 88812ns 00:53:27 I0930 00:53:26.471422 26519 hierarchical.cpp:1943] No allocations performed 00:53:27 I0930 00:53:26.471459 26519 hierarchical.cpp:2033] No inverse offers to send out! 00:53:27 I0930 00:53:26.471468 26519 hierarchical.cpp:1486] Performed allocation for 1 agents in 94159ns 00:53:28 I0930 00:53:27.471673 26520 hierarchical.cpp:1943] No allocations performed 00:53:28 I0930 00:53:27.471710 26520 hierarchical.cpp:2033] No inverse offers to send out! 00:53:28 I0930 00:53:27.471719 26520 hierarchical.cpp:1486] Performed allocation for 1 agents in 78489ns 00:53:29 I0930 00:53:28.472702 26517 hierarchical.cpp:1943] No allocations performed 00:53:29 I0930 00:53:28.472738 26517 hierarchical.cpp:2033] No inverse offers to send out! 00:53:29 I0930 00:53:28.472748 26517 hierarchical.cpp:1486] Performed allocation for 1 agents in 81729ns 00:53:30 I0930 00:53:29.472929 26519 hierarchical.cpp:1943] No allocations performed 00:53:30 I0930 00:53:29.472964 26519 hierarchical.cpp:2033] No inverse offers to send out! 00:53:30 I0930 00:53:29.472973 26519 hierarchical.cpp:1486] Performed allocation for 1 agents in 82132ns 00:53:31 I0930 00:53:30.473786 26516 hierarchical.cpp:1943] No allocations performed 00:53:31 I0930 00:53:30.473824 26516 hierarchical.cpp:2033] No inverse offers to send out! 00:53:31 I0930 00:53:30.473834 26516 hierarchical.cpp:1486] Performed allocation for 1 agents in 82223ns 00:53:32 I0930 00:53:31.474323 26519 hierarchical.cpp:1943] No allocations performed 00:53:32 I0930 00:53:31.474359 26519 hierarchical.cpp:2033] No inverse offers to send out! 00:53:32 I0930 00:53:31.474370 26519 hierarchical.cpp:1486] Performed allocation for 1 agents in 80471ns 00:53:33 I0930 00:53:32.475229 26517 hierarchical.cpp:1943] No allocations performed 00:53:33 I0930 00:53:32.475265 26517 hierarchical.cpp:2033] No inverse offers to send out! 00:53:33 I0930 00:53:32.475275 26517 hierarchical.cpp:1486] Performed allocation for 1 agents in 78854ns 00:53:34 I0930 00:53:33.476032 26520 hierarchical.cpp:1943] No allocations performed 00:53:34 I0930 00:53:33.476069 26520 hierarchical.cpp:2033] No inverse offers to send out! 00:53:34 I0930 00:53:33.476079 26520 hierarchical.cpp:1486] Performed allocation for 1 agents in 83997ns 00:53:35 I0930 00:53:34.477195 26518 hierarchical.cpp:1943] No allocations performed 00:53:35 I0930 00:53:34.477232 26518 hierarchical.cpp:2033] No inverse offers to send out! 00:53:35 I0930 00:53:34.477242 26518 hierarchical.cpp:1486] Performed allocation for 1 agents in 84326ns 00:53:36 I0930 00:53:35.478093 26521 hierarchical.cpp:1943] No allocations performed 00:53:36 I0930 00:53:35.478129 26521 hierarchical.cpp:2033] No inverse offers to send out! 00:53:36 I0930 00:53:35.478139 26521 hierarchical.cpp:1486] Performed allocation for 1 agents in 100064ns 00:53:37 I0930 00:53:36.478605 26522 hierarchical.cpp:1943] No allocations performed 00:53:37 I0930 00:53:36.478641 26522 hierarchical.cpp:2033] No inverse offers to send out! 00:53:37 I0930 00:53:36.478651 26522 hierarchical.cpp:1486] Performed allocation for 1 agents in 83366ns 00:53:38 I0930 00:53:37.479624 26523 hierarchical.cpp:1943] No allocations performed 00:53:38 I0930 00:53:37.479661 26523 hierarchical.cpp:2033] No inverse offers to send out! 00:53:38 I0930 00:53:37.479671 26523 hierarchical.cpp:1486] Performed allocation for 1 agents in 92555ns 00:53:39 I0930 00:53:38.480825 26516 hierarchical.cpp:1943] No allocations performed 00:53:39 I0930 00:53:38.480860 26516 hierarchical.cpp:2033] No inverse offers to send out! 00:53:39 I0930 00:53:38.480871 26516 hierarchical.cpp:1486] Performed allocation for 1 agents in 83078ns 00:53:39 I0930 00:53:39.481231 26519 hierarchical.cpp:1943] No allocations performed 00:53:39 I0930 00:53:39.481266 26519 hierarchical.cpp:2033] No inverse offers to send out! 00:53:39 I0930 00:53:39.481276 26519 hierarchical.cpp:1486] Performed allocation for 1 agents in 79973ns 00:53:39 I0930 00:53:39.485572 26518 master.hpp:349] Sending heartbeat to framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:39 I0930 00:53:39.485585 26523 slave.cpp:6495] Querying resource estimator for oversubscribable resources 00:53:39 I0930 00:53:39.485641 26523 slave.cpp:6509] Received oversubscribable resources {} from the resource estimator 00:53:39 ../../src/tests/containerizer/cni_isolator_tests.cpp:1419: Failure 00:53:39 Failed to wait 15secs for subscribed 00:53:39 I0930 00:53:39.485936 26520 scheduler.cpp:676] Enqueuing event HEARTBEAT received from http://172.16.10.96:38662/master/api/v1/scheduler 00:53:39 ../../src/tests/containerizer/cni_isolator_tests.cpp:1408: Failure 00:53:39 Actual function call count doesn't match EXPECT_CALL(*scheduler, subscribed(_, _))... 00:53:39 Expected: to be called once 00:53:39 Actual: never called - unsatisfied and active 00:53:39 I0930 00:53:39.486542 26517 master.cpp:1435] Framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) disconnected 00:53:39 I0930 00:53:39.486562 26517 master.cpp:3317] Deactivating framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 00:53:39 I0930 00:53:39.486608 26521 hierarchical.cpp:412] Deactivated framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:39 W0930 00:53:39.486692 26517 master.hpp:2560] Unable to send event to framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default): connection closed 00:53:39 I0930 00:53:39.486706 26517 master.cpp:9368] Removing offer 473b9c2c-8d12-417d-98de-d71cd175d503-O0 00:53:39 I0930 00:53:39.486721 26517 master.cpp:3294] Disconnecting framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 00:53:39 I0930 00:53:39.486732 26517 master.cpp:1450] Giving framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 0ns to failover 00:53:39 I0930 00:53:39.486759 26521 hierarchical.cpp:1161] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 from framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:39 I0930 00:53:39.487053 7413 slave.cpp:869] Agent terminating 00:53:39 I0930 00:53:39.487217 26522 master.cpp:1321] Agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) disconnected 00:53:39 I0930 00:53:39.487237 26522 master.cpp:3354] Disconnecting agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 00:53:39 I0930 00:53:39.487253 26522 master.cpp:3373] Deactivating agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 at slave(1065)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 00:53:39 I0930 00:53:39.487383 26523 hierarchical.cpp:690] Agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 deactivated 00:53:39 I0930 00:53:39.488117 26516 master.cpp:7577] Framework failover timeout, removing framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 00:53:39 I0930 00:53:39.488137 26516 master.cpp:8438] Removing framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 (default) 00:53:39 I0930 00:53:39.488229 26518 hierarchical.cpp:355] Removed framework 473b9c2c-8d12-417d-98de-d71cd175d503-0000 00:53:39 I0930 00:53:39.488982 7413 master.cpp:1163] Master terminating 00:53:39 I0930 00:53:39.489118 26519 hierarchical.cpp:626] Removed agent 473b9c2c-8d12-417d-98de-d71cd175d503-S0 00:53:39 [ FAILED ] NetworkParam/DefaultExecutorCniTest.ROOT_VerifyContainerIP/0, where GetParam() = Host Network (15023 ms) {noformat} > DefaultExecutorCniTest.ROOT_VerifyContainerIP is flaky. > ------------------------------------------------------- > > Key: MESOS-8000 > URL: https://issues.apache.org/jira/browse/MESOS-8000 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 1.5.0 > Environment: Ubuntu 16.04 > Reporter: Alexander Rukletsov > Labels: flaky-test, mesosphere > Attachments: ROOT_VerifyContainerIP_badrun.txt, > ROOT_VerifyContainerIP_goodrun.txt > > > Observed a failure on internal CI: > {noformat} > ../../src/tests/containerizer/cni_isolator_tests.cpp:1419 > Failed to wait 15secs for subscribed > {noformat} > Full log attached. -- This message was sent by Atlassian JIRA (v6.4.14#64029)