[
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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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 [email protected]: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
[email protected]: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)
