Andrei Sekretenko created MESOS-10021:
-----------------------------------------
Summary:
CgroupsIsolatorTest.ROOT_CGROUPS_NestedContainerSpecificCgroupsMount is flaky
Key: MESOS-10021
URL: https://issues.apache.org/jira/browse/MESOS-10021
Project: Mesos
Issue Type: Bug
Affects Versions: 1.9.0
Reporter: Andrei Sekretenko
Observed in an internal CI.
Looks like the TASK_RUNNING update has never reached the framework and, most
likely, has never been generated:
{code}
[ RUN ]
CgroupsIsolatorTest.ROOT_CGROUPS_NestedContainerSpecificCgroupsMount
I1029 18:39:30.830571 597 cluster.cpp:177] Creating default 'local' authorizer
I1029 18:39:30.831876 20699 master.cpp:440] Master
68270ce9-2cc9-4146-9122-2c124f69e914 (ip-172-16-10-99.ec2.internal) started on
172.16.10.99:33587
I1029 18:39:30.831897 20699 master.cpp:443] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/91gVso/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_operator_event_stream_subscribers="1000"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="true" --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"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/91gVso/master" --zk_session_timeout="10secs"
I1029 18:39:30.832020 20699 master.cpp:492] Master only allowing authenticated
frameworks to register
I1029 18:39:30.832042 20699 master.cpp:498] Master only allowing authenticated
agents to register
I1029 18:39:30.832053 20699 master.cpp:504] Master only allowing authenticated
HTTP frameworks to register
I1029 18:39:30.832059 20699 credentials.hpp:37] Loading credentials for
authentication from '/tmp/91gVso/credentials'
I1029 18:39:30.832140 20699 master.cpp:548] Using default 'crammd5'
authenticator
I1029 18:39:30.832207 20699 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1029 18:39:30.832257 20699 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1029 18:39:30.832314 20699 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1029 18:39:30.832365 20699 master.cpp:629] Authorization enabled
I1029 18:39:30.832471 20702 hierarchical.cpp:474] Initialized hierarchical
allocator process
I1029 18:39:30.832559 20696 whitelist_watcher.cpp:77] No whitelist given
I1029 18:39:30.833153 20700 master.cpp:2170] Elected as the leading master!
I1029 18:39:30.833175 20700 master.cpp:1666] Recovering from registrar
I1029 18:39:30.833225 20697 registrar.cpp:339] Recovering registrar
I1029 18:39:30.833390 20697 registrar.cpp:383] Successfully fetched the
registry (0B) in 141056ns
I1029 18:39:30.833431 20697 registrar.cpp:487] Applied 1 operations in 8774ns;
attempting to update the registry
I1029 18:39:30.833613 20702 registrar.cpp:544] Successfully updated the
registry in 163072ns
I1029 18:39:30.833663 20702 registrar.cpp:416] Successfully recovered registrar
I1029 18:39:30.833783 20702 master.cpp:1819] Recovered 0 agents from the
registry (180B); allowing 10mins for agents to reregister
I1029 18:39:30.833801 20700 hierarchical.cpp:513] Skipping recovery of
hierarchical allocator: nothing to recover
W1029 18:39:30.834903 597 process.cpp:2877] Attempted to spawn already
running process files@172.16.10.99:33587
I1029 18:39:30.835351 597 containerizer.cpp:318] Using isolation {
volume/sandbox_path, volume/host_path, volume/image, network/cni,
environment_secret, cgroups/mem, cgroups/cpu, docker/runtime, filesystem/linux }
I1029 18:39:30.837710 597 linux_launcher.cpp:144] Using
/sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I1029 18:39:30.838220 597 provisioner.cpp:294] Using default backend 'overlay'
sh: 1: hadoop: not found
I1029 18:39:30.944325 597 fetcher.cpp:68] Skipping URI fetcher plugin
'hadoop' as it could not be created: Failed to create HDFS client: Hadoop
client is not available, exit status: 32512
I1029 18:39:30.944428 597 registry_puller.cpp:150] Creating registry puller
with docker registry 'https://registry-1.docker.io'
I1029 18:39:30.952987 597 cluster.cpp:518] Creating default 'local' authorizer
I1029 18:39:30.953733 20698 slave.cpp:267] Mesos agent started on
(820)@172.16.10.99:33587
I1029 18:39:30.953754 20698 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/91gVso/gxhI0o/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="false" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/tmp/91gVso/gxhI0o/credential" --default_role="*"
--disallow_sharing_agent_ipc_namespace="false"
--disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins"
--docker="docker" --docker_ignore_runtime="false" --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/91gVso/gxhI0o/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--docker_volume_chown="false" --enforce_container_disk_quota="false"
--executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/91gVso/gxhI0o/fetch" --fetcher_cache_size="2GB"
--fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/91gVso/gxhI0o/frameworks" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false"
--help="false" --hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/91gVso/gxhI0o/http_credentials"
--http_heartbeat_interval="30secs" --image_providers="docker"
--initialize_driver_logging="true"
--isolation="filesystem/linux,docker/runtime,cgroups/mem,cgroups/cpu"
--jwt_secret_key="/tmp/91gVso/gxhI0o/jwt_secret_key" --launcher="linux"
--launcher_dir="/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-16.04/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --network_cni_root_dir_persist="false"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --reconfiguration_policy="equal" --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/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_vMZ693"
--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/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ"
--zk_session_timeout="10secs"
I1029 18:39:30.953974 20698 credentials.hpp:86] Loading credential for
authentication from '/tmp/91gVso/gxhI0o/credential'
I1029 18:39:30.954028 20698 slave.cpp:300] Agent using credential for:
test-principal
I1029 18:39:30.954041 20698 credentials.hpp:37] Loading credentials for
authentication from '/tmp/91gVso/gxhI0o/http_credentials'
I1029 18:39:30.954205 20698 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I1029 18:39:30.954258 20698 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I1029 18:39:30.954346 20698 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1029 18:39:30.954385 597 scheduler.cpp:189] Version: 1.9.1
I1029 18:39:30.954401 20698 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I1029 18:39:30.954550 20698 disk_profile_adaptor.cpp:78] Creating default disk
profile adaptor module
I1029 18:39:30.954891 20702 scheduler.cpp:342] Using default 'basic' HTTP
authenticatee
I1029 18:39:30.955106 20698 slave.cpp:615] 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"}]
I1029 18:39:30.955153 20699 scheduler.cpp:525] New master detected at
master@172.16.10.99:33587
I1029 18:39:30.955168 20698 slave.cpp:623] Agent attributes: [ ]
I1029 18:39:30.955178 20698 slave.cpp:632] Agent hostname:
ip-172-16-10-99.ec2.internal
I1029 18:39:30.955250 20701 task_status_update_manager.cpp:181] Pausing sending
task status updates
I1029 18:39:30.955307 20701 status_update_manager_process.hpp:379] Pausing
operation status update manager
I1029 18:39:30.955601 20702 state.cpp:67] Recovering state from
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/meta'
I1029 18:39:30.955678 20700 slave.cpp:7492] Finished recovering checkpointed
state from
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/meta',
beginning agent recovery
I1029 18:39:30.955770 20700 task_status_update_manager.cpp:207] Recovering task
status update manager
I1029 18:39:30.955925 20703 containerizer.cpp:821] Recovering Mesos containers
I1029 18:39:30.956080 20696 linux_launcher.cpp:286] Recovering Linux launcher
I1029 18:39:30.956115 20699 scheduler.cpp:534] Waiting for 0ns before
initiating a re-(connection) attempt with the master
I1029 18:39:30.956329 20696 containerizer.cpp:1161] Recovering isolators
I1029 18:39:30.957005 20700 scheduler.cpp:416] Connected with the master at
http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.957275 20703 scheduler.cpp:246] Adding authentication headers to
SUBSCRIBE call to http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.957348 20698 containerizer.cpp:1200] Recovering provisioner
I1029 18:39:30.957437 20700 scheduler.cpp:600] Sending SUBSCRIBE call to
http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.957540 20701 metadata_manager.cpp:244] No images to load from
disk. Docker provisioner image storage path
'/tmp/91gVso/gxhI0o/store/docker/storedImages' does not exist
I1029 18:39:30.957674 20696 provisioner.cpp:518] Provisioner recovery complete
I1029 18:39:30.957794 20700 process.cpp:3671] Handling HTTP event for process
'master' with path: '/master/api/v1/scheduler'
I1029 18:39:30.957965 20696 composing.cpp:339] Finished recovering all
containerizers
I1029 18:39:30.958096 20702 slave.cpp:7973] Recovering executors
I1029 18:39:30.958143 20702 slave.cpp:8126] Finished recovery
I1029 18:39:30.958364 20696 http.cpp:1115] HTTP POST for
/master/api/v1/scheduler from 172.16.10.99:45596
I1029 18:39:30.958463 20696 master.cpp:2670] Received subscription request for
HTTP framework 'default'
I1029 18:39:30.958497 20696 master.cpp:2242] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I1029 18:39:30.958541 20702 slave.cpp:1351] New master detected at
master@172.16.10.99:33587
I1029 18:39:30.958555 20701 task_status_update_manager.cpp:181] Pausing sending
task status updates
I1029 18:39:30.958575 20700 status_update_manager_process.hpp:379] Pausing
operation status update manager
I1029 18:39:30.958590 20702 slave.cpp:1416] Detecting new master
I1029 18:39:30.958789 20701 master.cpp:2742] Subscribing framework 'default'
with checkpointing disabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I1029 18:39:30.959276 20701 master.cpp:10847] Adding framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) with roles { } suppressed
I1029 18:39:30.959522 20697 hierarchical.cpp:605] Added framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.959627 20697 hierarchical.cpp:1734] Performed allocation for 0
agents in 23045ns
I1029 18:39:30.959761 20702 scheduler.cpp:847] Enqueuing event SUBSCRIBED
received from http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.959934 20702 scheduler.cpp:847] Enqueuing event HEARTBEAT
received from http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.965926 20698 slave.cpp:1443] Authenticating with master
master@172.16.10.99:33587
I1029 18:39:30.965957 20698 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I1029 18:39:30.966042 20696 authenticatee.cpp:121] Creating new client SASL
connection
I1029 18:39:30.966497 20696 master.cpp:10617] Authenticating
slave(820)@172.16.10.99:33587
I1029 18:39:30.966567 20700 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1562)@172.16.10.99:33587
I1029 18:39:30.966665 20702 authenticator.cpp:98] Creating new server SASL
connection
I1029 18:39:30.967026 20699 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1029 18:39:30.967051 20699 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1029 18:39:30.967089 20699 authenticator.cpp:204] Received SASL authentication
start
I1029 18:39:30.967118 20699 authenticator.cpp:326] Authentication requires more
steps
I1029 18:39:30.967164 20699 authenticatee.cpp:259] Received SASL authentication
step
I1029 18:39:30.967221 20699 authenticator.cpp:232] Received SASL authentication
step
I1029 18:39:30.967245 20699 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-99.ec2.internal' server FQDN:
'ip-172-16-10-99.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 18:39:30.967253 20699 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1029 18:39:30.967267 20699 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1029 18:39:30.967275 20699 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-99.ec2.internal' server FQDN:
'ip-172-16-10-99.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 18:39:30.967281 20699 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 18:39:30.967286 20699 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 18:39:30.967296 20699 authenticator.cpp:318] Authentication success
I1029 18:39:30.967353 20703 authenticatee.cpp:299] Authentication success
I1029 18:39:30.967360 20700 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1562)@172.16.10.99:33587
I1029 18:39:30.967454 20696 master.cpp:10649] Successfully authenticated
principal 'test-principal' at slave(820)@172.16.10.99:33587
I1029 18:39:30.967558 20702 slave.cpp:1543] Successfully authenticated with
master master@172.16.10.99:33587
I1029 18:39:30.967670 20702 slave.cpp:1993] Will retry registration in
9.838483ms if necessary
I1029 18:39:30.967720 20701 master.cpp:7088] Received register agent message
from slave(820)@172.16.10.99:33587 (ip-172-16-10-99.ec2.internal)
I1029 18:39:30.967811 20701 master.cpp:4204] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I1029 18:39:30.967965 20699 master.cpp:7155] Authorized registration of agent
at slave(820)@172.16.10.99:33587 (ip-172-16-10-99.ec2.internal)
I1029 18:39:30.968011 20699 master.cpp:7267] Registering agent at
slave(820)@172.16.10.99:33587 (ip-172-16-10-99.ec2.internal) with id
68270ce9-2cc9-4146-9122-2c124f69e914-S0
I1029 18:39:30.968161 20697 registrar.cpp:487] Applied 1 operations in 42085ns;
attempting to update the registry
I1029 18:39:30.968333 20697 registrar.cpp:544] Successfully updated the
registry in 137984ns
I1029 18:39:30.968400 20696 master.cpp:7315] Admitted agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:30.968559 20696 master.cpp:7360] Registered agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal) with cpus:2; mem:1024; disk:1024;
ports:[31000-32000]
I1029 18:39:30.968611 20703 slave.cpp:1576] Registered with master
master@172.16.10.99:33587; given agent ID
68270ce9-2cc9-4146-9122-2c124f69e914-S0
I1029 18:39:30.968618 20698 hierarchical.cpp:858] Added agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 (ip-172-16-10-99.ec2.internal) with
cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I1029 18:39:30.968681 20700 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1029 18:39:30.968796 20703 slave.cpp:1611] Checkpointing SlaveInfo to
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/meta/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/slave.info'
I1029 18:39:30.968806 20698 hierarchical.cpp:1734] Performed allocation for 1
agents in 104679ns
I1029 18:39:30.968822 20701 status_update_manager_process.hpp:385] Resuming
operation status update manager
I1029 18:39:30.968976 20697 master.cpp:10432] Sending offers [
68270ce9-2cc9-4146-9122-2c124f69e914-O0 ] to framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:30.969113 20703 slave.cpp:1663] Forwarding agent update
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"92vuvDO4RnyTRGtbe7li6Q=="},"slave_id":{"value":"68270ce9-2cc9-4146-9122-2c124f69e914-S0"},"update_oversubscribed_resources":false}
I1029 18:39:30.969278 20703 master.cpp:8487] Ignoring update on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal) as it reports no changes
I1029 18:39:30.969430 20702 scheduler.cpp:847] Enqueuing event OFFERS received
from http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.970034 20700 scheduler.cpp:246] Adding authentication headers to
ACCEPT call to http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.970214 20696 scheduler.cpp:600] Sending ACCEPT call to
http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:30.970475 20702 process.cpp:3671] Handling HTTP event for process
'master' with path: '/master/api/v1/scheduler'
I1029 18:39:30.970788 20696 http.cpp:1115] HTTP POST for
/master/api/v1/scheduler from 172.16.10.99:45594
I1029 18:39:30.970968 20696 master.cpp:12724] Removing offer
68270ce9-2cc9-4146-9122-2c124f69e914-O0
I1029 18:39:30.971102 20696 master.cpp:4741] Processing ACCEPT call for offers:
[ 68270ce9-2cc9-4146-9122-2c124f69e914-O0 ] on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal) for framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:30.971164 20696 master.cpp:3758] Authorizing framework principal
'test-principal' to launch task 08db2439-e4af-4917-9635-d7f1adef0417
I1029 18:39:30.971674 20696 master.cpp:4276] Adding executor
'test_default_executor' with resources cpus(allocated: *):0.1; mem(allocated:
*):32; disk(allocated: *):32 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:30.971771 20696 master.cpp:4302] Adding task
08db2439-e4af-4917-9635-d7f1adef0417 with resources cpus(allocated: *):0.1;
mem(allocated: *):32; disk(allocated: *):32 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:30.971858 20696 master.cpp:5943] Launching task group {
08db2439-e4af-4917-9635-d7f1adef0417 } of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) with resources
cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal) on new executor
I1029 18:39:30.972010 20698 hierarchical.cpp:1658] Allocation paused
I1029 18:39:30.972079 20700 slave.cpp:2130] Got assigned task group containing
tasks [ 08db2439-e4af-4917-9635-d7f1adef0417 ] for framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.972182 20698 hierarchical.cpp:1460] Recovered ports(allocated:
*):[31000-32000]; cpus(allocated: *):1.8; mem(allocated: *):960;
disk(allocated: *):960 (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: disk(allocated: *):64; cpus(allocated: *):0.2;
mem(allocated: *):64) on agent 68270ce9-2cc9-4146-9122-2c124f69e914-S0 from
framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.972229 20698 hierarchical.cpp:1506] Framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 filtered agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for 5secs
I1029 18:39:30.972307 20698 hierarchical.cpp:1668] Allocation resumed
I1029 18:39:30.972467 20700 slave.cpp:2504] Authorizing task group containing
tasks [ 08db2439-e4af-4917-9635-d7f1adef0417 ] for framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.972512 20700 slave.cpp:9465] Authorizing framework principal
'test-principal' to launch task 08db2439-e4af-4917-9635-d7f1adef0417
I1029 18:39:30.973096 20700 slave.cpp:2977] Launching task group containing
tasks [ 08db2439-e4af-4917-9635-d7f1adef0417 ] for framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.973143 20700 paths.cpp:817] Creating sandbox
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
for user 'root'
I1029 18:39:30.973748 20700 slave.cpp:10003] Launching executor
'test_default_executor' of framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
I1029 18:39:30.973994 20700 slave.cpp:3209] Queued task group containing tasks
[ 08db2439-e4af-4917-9635-d7f1adef0417 ] for executor 'test_default_executor'
of framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.974046 20700 slave.cpp:1084] Successfully attached
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
to virtual path
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/latest'
I1029 18:39:30.974074 20700 slave.cpp:1084] Successfully attached
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
to virtual path
'/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/latest'
I1029 18:39:30.974231 20700 slave.cpp:1084] Successfully attached
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
to virtual path
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32'
I1029 18:39:30.974323 20700 slave.cpp:3657] Launching container
70b22332-6c59-4c4b-b2c2-01e043155e32 for executor 'test_default_executor' of
framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:30.974499 20702 containerizer.cpp:1396] Starting container
70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.974617 20702 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from STARTING to PROVISIONING
after 46080ns
I1029 18:39:30.974825 20702 containerizer.cpp:1574] Checkpointed
ContainerConfig at
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_vMZ693/containers/70b22332-6c59-4c4b-b2c2-01e043155e32/config'
I1029 18:39:30.974850 20702 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from PROVISIONING to PREPARING
after 235008ns
I1029 18:39:30.975217 20696 cgroups.cpp:434] Creating cgroup at
'/sys/fs/cgroup/cpu,cpuacct/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32'
for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.975576 20696 cgroups.cpp:490] Chown the cgroup at
'/sys/fs/cgroup/cpu,cpuacct/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32'
to user 'root' for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.975658 20696 cgroups.cpp:434] Creating cgroup at
'/sys/fs/cgroup/memory/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32'
for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.975975 20696 cgroups.cpp:490] Chown the cgroup at
'/sys/fs/cgroup/memory/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32'
to user 'root' for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976058 20697 memory.cpp:478] Started listening for OOM events
for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976130 20697 memory.cpp:590] Started listening on 'low' memory
pressure events for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976184 20697 memory.cpp:590] Started listening on 'medium'
memory pressure events for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976227 20697 memory.cpp:590] Started listening on 'critical'
memory pressure events for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976446 20696 memory.cpp:198] Updated
'memory.soft_limit_in_bytes' to 64MB for container
70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976513 20703 cpu.cpp:92] Updated 'cpu.shares' to 204 (cpus 0.2)
for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.976524 20696 memory.cpp:227] Updated 'memory.limit_in_bytes' to
64MB for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:30.977605 20698 containerizer.cpp:2100] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"clone_namespaces":[131072],"command":{"arguments":["mesos-default-executor","--launcher_dir=/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-16.04/mesos/build/src"],"shell":false,"value":"/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-16.04/mesos/build/src/mesos-default-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.16.10.99:33587"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiI3MGIyMjMzMi02YzU5LTRjNGItYjJjMi0wMWUwNDMxNTVlMzIiLCJlaWQiOiJ0ZXN0X2RlZmF1bHRfZXhlY3V0b3IiLCJmaWQiOiI2ODI3MGNlOS0yY2M5LTQxNDYtOTEyMi0yYzEyNGY2OWU5MTQtMDAwMCJ9.2R1Lzk4hWgpGT8nsm2j_gV5uPo9HJfQmDrOVJBFb-BM"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"test_default_executor"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"68270ce9-2cc9-4146-9122-2c124f69e914-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"68270ce9-2cc9-4146-9122-2c124f69e914-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(820)@172.16.10.99:33587"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32"}]},"task_environment":{},"user":"root","working_directory":"/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32"}"
--pipe_read="71" --pipe_write="72"
--runtime_directory="/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_vMZ693/containers/70b22332-6c59-4c4b-b2c2-01e043155e32"
--unshare_namespace_mnt="false"'
I1029 18:39:30.977777 20701 linux_launcher.cpp:492] Launching container
70b22332-6c59-4c4b-b2c2-01e043155e32 and cloning with namespaces CLONE_NEWNS
I1029 18:39:30.999146 20698 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from PREPARING to ISOLATING
after 24.252928ms
I1029 18:39:31.000881 20702 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from ISOLATING to FETCHING after
1.729024ms
I1029 18:39:31.000950 20702 fetcher.cpp:369] Starting to fetch URIs for
container: 70b22332-6c59-4c4b-b2c2-01e043155e32, directory:
/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:31.001241 20702 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from FETCHING to RUNNING after
407040ns
Marked '/' as rslave
I1029 18:39:31.115031 20993 executor.cpp:206] Version: 1.9.1
I1029 18:39:31.117492 20698 process.cpp:3671] Handling HTTP event for process
'slave(820)' with path: '/slave(820)/api/v1/executor'
I1029 18:39:31.118289 20699 http.cpp:1115] HTTP POST for
/slave(820)/api/v1/executor from 172.16.10.99:45598
I1029 18:39:31.118386 20699 slave.cpp:5028] Received Subscribe request for HTTP
executor 'test_default_executor' of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.119251 20700 cpu.cpp:92] Updated 'cpu.shares' to 204 (cpus 0.2)
for container 70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:31.119362 20702 memory.cpp:198] Updated
'memory.soft_limit_in_bytes' to 64MB for container
70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:31.119746 20697 slave.cpp:3468] Sending queued task group
containing tasks [ 08db2439-e4af-4917-9635-d7f1adef0417 ] to executor
'test_default_executor' of framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
(via HTTP)
I1029 18:39:31.119748 20996 default_executor.cpp:205] Received SUBSCRIBED event
I1029 18:39:31.120051 20996 default_executor.cpp:209] Subscribed executor on
ip-172-16-10-99.ec2.internal
I1029 18:39:31.120478 21001 default_executor.cpp:205] Received LAUNCH_GROUP
event
I1029 18:39:31.120756 21001 default_executor.cpp:433] Setting
'MESOS_CONTAINER_IP' to: 172.16.10.99
I1029 18:39:31.121866 20699 process.cpp:3671] Handling HTTP event for process
'slave(820)' with path: '/slave(820)/api/v1/executor'
I1029 18:39:31.122012 20699 process.cpp:3671] Handling HTTP event for process
'slave(820)' with path: '/slave(820)/api/v1'
I1029 18:39:31.122496 20698 http.cpp:1115] HTTP POST for
/slave(820)/api/v1/executor from 172.16.10.99:45600
I1029 18:39:31.122565 20698 slave.cpp:5737] Handling status update
TASK_STARTING (Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.122678 20698 http.cpp:1115] HTTP POST for /slave(820)/api/v1
from 172.16.10.99:45602
I1029 18:39:31.122817 20700 task_status_update_manager.cpp:328] Received task
status update TASK_STARTING (Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7)
for task 08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.122848 20698 http.cpp:2574] Processing LAUNCH_NESTED_CONTAINER
call for container
'70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7'
I1029 18:39:31.122869 20700 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.123070 20700 task_status_update_manager.cpp:383] Forwarding task
status update TASK_STARTING (Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7)
for task 08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 to the agent
I1029 18:39:31.123137 20702 slave.cpp:6277] Forwarding the update TASK_STARTING
(Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 to master@172.16.10.99:33587
I1029 18:39:31.123208 20698 containerizer.cpp:1358] Creating sandbox
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_7vWvjJ/slaves/68270ce9-2cc9-4146-9122-2c124f69e914-S0/frameworks/68270ce9-2cc9-4146-9122-2c124f69e914-0000/executors/test_default_executor/runs/70b22332-6c59-4c4b-b2c2-01e043155e32/containers/615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7'
for user 'root'
I1029 18:39:31.123237 20702 slave.cpp:6161] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.123396 20697 master.cpp:8985] Status update TASK_STARTING
(Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 from agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:31.123438 20697 master.cpp:9042] Forwarding status update
TASK_STARTING (Status UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.123486 20698 containerizer.cpp:1396] Starting container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7
I1029 18:39:31.123620 20698 containerizer.cpp:3318] Transitioning the state of
container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7 from
STARTING to PROVISIONING after 52992ns
I1029 18:39:31.123721 20994 default_executor.cpp:205] Received ACKNOWLEDGED
event
I1029 18:39:31.123723 20697 master.cpp:12073] Updating the state of task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)
I1029 18:39:31.123842 20702 metadata_manager.cpp:165] Looking for image 'alpine'
I1029 18:39:31.123967 20703 scheduler.cpp:847] Enqueuing event UPDATE received
from http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:31.124011 20696 store.cpp:349] Pulling image 'alpine'
I1029 18:39:31.124151 20696 registry_puller.cpp:308] Fetching manifest from
'docker-manifest://registry-1.docker.io:443library/alpine?latest#https' to
'/tmp/91gVso/gxhI0o/store/docker/staging/NQtEdt' for image 'library/alpine'
I1029 18:39:31.124351 20697 scheduler.cpp:246] Adding authentication headers to
ACKNOWLEDGE call to http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:31.129055 20700 scheduler.cpp:600] Sending ACKNOWLEDGE call to
http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:31.129810 20698 process.cpp:3671] Handling HTTP event for process
'master' with path: '/master/api/v1/scheduler'
I1029 18:39:31.166676 20697 http.cpp:1115] HTTP POST for
/master/api/v1/scheduler from 172.16.10.99:45594
I1029 18:39:31.166767 20697 master.cpp:6695] Processing ACKNOWLEDGE call for
status f102d20c-906d-4efb-b4e4-5d70dadaf7c7 for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0
I1029 18:39:31.166959 20702 task_status_update_manager.cpp:401] Received task
status update acknowledgement (UUID: f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for
task 08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.167104 20702 slave.cpp:4866] Task status update manager
successfully handled status update acknowledgement (UUID:
f102d20c-906d-4efb-b4e4-5d70dadaf7c7) for task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.750885 20703 registry_puller.cpp:335] The manifest for image
'alpine' is '{
"schemaVersion": 2,
"mediaType": "application/vnd.docker.distribution.manifest.v2+json",
"config": {
"mediaType": "application/vnd.docker.container.image.v1+json",
"size": 1512,
"digest":
"sha256:965ea09ff2ebd2b9eeec88cd822ce156f6674c7e99be082c7efac3c62f3ff652"
},
"layers": [
{
"mediaType": "application/vnd.docker.image.rootfs.diff.tar.gzip",
"size": 2787134,
"digest":
"sha256:89d9c30c1d48bac627e5c6cb0d1ed1eec28e7dbdfbcc04712e4c79c0f83faf17"
}
]
}'
I1029 18:39:31.750991 20703 registry_puller.cpp:646] Fetching config
'sha256:965ea09ff2ebd2b9eeec88cd822ce156f6674c7e99be082c7efac3c62f3ff652' to
'/tmp/91gVso/gxhI0o/store/docker/staging/NQtEdt' for image 'library/alpine'
I1029 18:39:31.751013 20703 registry_puller.cpp:652] Fetching layers to
'/tmp/91gVso/gxhI0o/store/docker/staging/NQtEdt' for image 'library/alpine'
I1029 18:39:31.751044 20703 registry_puller.cpp:664] Fetching layer
'sha256:89d9c30c1d48bac627e5c6cb0d1ed1eec28e7dbdfbcc04712e4c79c0f83faf17' to
'/tmp/91gVso/gxhI0o/store/docker/staging/NQtEdt' for image 'library/alpine'
I1029 18:39:31.833449 20701 hierarchical.cpp:2589] Filtered offer with
ports:[31000-32000]; cpus:1.8; mem:960; disk:960 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for role * of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:31.833534 20701 hierarchical.cpp:1734] Performed allocation for 1
agents in 203286ns
I1029 18:39:32.834789 20701 hierarchical.cpp:2589] Filtered offer with
ports:[31000-32000]; cpus:1.8; mem:960; disk:960 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for role * of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:32.834888 20701 hierarchical.cpp:1734] Performed allocation for 1
agents in 187879ns
I1029 18:39:33.835907 20702 hierarchical.cpp:2589] Filtered offer with
ports:[31000-32000]; cpus:1.8; mem:960; disk:960 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for role * of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:33.835985 20702 hierarchical.cpp:1734] Performed allocation for 1
agents in 215379ns
I1029 18:39:34.836555 20698 hierarchical.cpp:2589] Filtered offer with
ports:[31000-32000]; cpus:1.8; mem:960; disk:960 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for role * of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:34.836618 20698 hierarchical.cpp:1734] Performed allocation for 1
agents in 133874ns
I1029 18:39:35.837388 20702 hierarchical.cpp:2589] Filtered offer with
ports:[31000-32000]; cpus:1.8; mem:960; disk:960 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 for role * of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:35.837466 20702 hierarchical.cpp:1734] Performed allocation for 1
agents in 156870ns
I1029 18:39:36.838723 20698 hierarchical.cpp:1734] Performed allocation for 1
agents in 186763ns
I1029 18:39:36.838965 20697 master.cpp:10432] Sending offers [
68270ce9-2cc9-4146-9122-2c124f69e914-O1 ] to framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:36.839593 20700 scheduler.cpp:847] Enqueuing event OFFERS received
from http://172.16.10.99:33587/master/api/v1/scheduler
I1029 18:39:37.839359 20696 hierarchical.cpp:1734] Performed allocation for 1
agents in 42294ns
I1029 18:39:38.840049 20701 hierarchical.cpp:1734] Performed allocation for 1
agents in 38014ns
I1029 18:39:39.840997 20698 hierarchical.cpp:1734] Performed allocation for 1
agents in 35686ns
I1029 18:39:40.842062 20697 hierarchical.cpp:1734] Performed allocation for 1
agents in 42436ns
I1029 18:39:41.843065 20698 hierarchical.cpp:1734] Performed allocation for 1
agents in 40253ns
I1029 18:39:42.843704 20697 hierarchical.cpp:1734] Performed allocation for 1
agents in 41100ns
I1029 18:39:43.844401 20703 hierarchical.cpp:1734] Performed allocation for 1
agents in 42623ns
I1029 18:39:44.845052 20700 hierarchical.cpp:1734] Performed allocation for 1
agents in 41411ns
I1029 18:39:45.846113 20701 hierarchical.cpp:1734] Performed allocation for 1
agents in 43218ns
I1029 18:39:45.960790 20703 scheduler.cpp:847] Enqueuing event HEARTBEAT
received from http://172.16.10.99:33587/master/api/v1/scheduler
../../src/tests/containerizer/cgroups_isolator_tests.cpp:2282: Failure
Failed to wait 15secs for runningUpdate
I1029 18:39:46.129278 20696 master.cpp:1412] Framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) disconnected
I1029 18:39:46.129313 20696 master.cpp:3362] Deactivating framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:46.129420 20702 hierarchical.cpp:711] Deactivated framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
W1029 18:39:46.129518 20696 master.hpp:2709] Unable to send message to
framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default): connection closed
I1029 18:39:46.129541 20696 master.cpp:12724] Removing offer
68270ce9-2cc9-4146-9122-2c124f69e914-O1
I1029 18:39:46.129570 20696 master.cpp:3339] Disconnecting framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:46.129560 20702 hierarchical.cpp:1460] Recovered ports(allocated:
*):[31000-32000]; cpus(allocated: *):1.8; mem(allocated: *):960;
disk(allocated: *):960 (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: disk(allocated: *):64; cpus(allocated: *):0.2;
mem(allocated: *):64) on agent 68270ce9-2cc9-4146-9122-2c124f69e914-S0 from
framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:46.129586 20696 master.cpp:1427] Giving framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default) 0ns to failover
I1029 18:39:46.129695 20703 master.cpp:10224] Framework failover timeout,
removing framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:46.129715 20703 master.cpp:11223] Removing framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (default)
I1029 18:39:46.129791 20703 master.cpp:12073] Updating the state of task
08db2439-e4af-4917-9635-d7f1adef0417 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I1029 18:39:46.129814 20697 slave.cpp:4062] Asked to shut down framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 by master@172.16.10.99:33587
I1029 18:39:46.129838 20697 slave.cpp:4087] Shutting down framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:46.129858 20697 slave.cpp:7223] Shutting down executor
'test_default_executor' of framework 68270ce9-2cc9-4146-9122-2c124f69e914-0000
(via HTTP)
I1029 18:39:46.129918 20703 master.cpp:12171] Removing task
08db2439-e4af-4917-9635-d7f1adef0417 with resources cpus(allocated: *):0.1;
mem(allocated: *):32; disk(allocated: *):32 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:46.129951 20700 hierarchical.cpp:1460] Recovered cpus(allocated:
*):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024;
disk:1024; ports:[31000-32000], allocated: disk(allocated: *):32;
cpus(allocated: *):0.1; mem(allocated: *):32) on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 from framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:46.130041 20703 master.cpp:12211] Removing executor
'test_default_executor' with resources cpus(allocated: *):0.1; mem(allocated:
*):32; disk(allocated: *):32 of framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:46.130216 20701 hierarchical.cpp:1460] Recovered cpus(allocated:
*):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024;
disk:1024; ports:[31000-32000], allocated: {}) on agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 from framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:46.130264 20701 hierarchical.cpp:1658] Allocation paused
I1029 18:39:46.130367 20701 hierarchical.cpp:655] Removed framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000
I1029 18:39:46.130403 20701 hierarchical.cpp:1668] Allocation resumed
I1029 18:39:46.130475 21000 default_executor.cpp:205] Received SHUTDOWN event
../../src/tests/containerizer/cgroups_isolator_tests.cpp:2260: Failure
Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_,
_))...
Expected: to be called 3 times
Actual: called once - unsatisfied and active
I1029 18:39:46.130507 21000 default_executor.cpp:1037] Shutting down
I1029 18:39:46.130724 597 slave.cpp:924] Agent terminating
I1029 18:39:46.130759 597 slave.cpp:4062] Asked to shut down framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 by @0.0.0.0:0
W1029 18:39:46.130781 597 slave.cpp:4083] Ignoring shutdown framework
68270ce9-2cc9-4146-9122-2c124f69e914-0000 because it is terminating
I1029 18:39:46.131156 20697 master.cpp:1297] Agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal) disconnected
I1029 18:39:46.131191 20697 master.cpp:3399] Disconnecting agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:46.131227 20697 master.cpp:3418] Deactivating agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 at slave(820)@172.16.10.99:33587
(ip-172-16-10-99.ec2.internal)
I1029 18:39:46.131300 20697 hierarchical.cpp:1047] Agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0 deactivated
I1029 18:39:46.131454 20702 containerizer.cpp:2620] Destroying container
70b22332-6c59-4c4b-b2c2-01e043155e32 in RUNNING state
I1029 18:39:46.131479 20702 containerizer.cpp:3318] Transitioning the state of
container 70b22332-6c59-4c4b-b2c2-01e043155e32 from RUNNING to DESTROYING after
15.130241024secs
I1029 18:39:46.131494 20702 containerizer.cpp:2620] Destroying container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7 in
PROVISIONING state
I1029 18:39:46.131508 20702 containerizer.cpp:3318] Transitioning the state of
container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7 from
PROVISIONING to DESTROYING after 15.007890944secs
I1029 18:39:46.131611 20702 containerizer.cpp:2682] Discarding the provisioning
for container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7
I1029 18:39:46.131690 20702 process.cpp:3733] Failed to process request for
'/slave(820)/api/v1': discarded
I1029 18:39:46.131712 20697 http_proxy.cpp:132] Returning '500 Internal Server
Error' for '/slave(820)/api/v1' (discarded)
I1029 18:39:46.131953 20698 docker.cpp:89] 'curl -s -S -L -i --raw --http1.1 -y
60
https://registry-1.docker.io:443/v2/library/alpine/blobs/sha256:965ea09ff2ebd2b9eeec88cd822ce156f6674c7e99be082c7efac3c62f3ff652'
is being discarded
I1029 18:39:46.131976 20696 provisioner.cpp:652] Ignoring destroy request for
unknown container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7
W1029 18:39:46.132045 20997 default_executor.cpp:551] Ignoring the launch group
operation as the executor is shutting down
I1029 18:39:46.132091 20701 store.cpp:362] Removing staging directory
'/tmp/91gVso/gxhI0o/store/docker/staging/NQtEdt'
I1029 18:39:46.132118 20699 containerizer.cpp:2938] Checkpointing termination
state to nested container's runtime directory
'/tmp/CgroupsIsolatorTest_ROOT_CGROUPS_NestedContainerSpecificCgroupsMount_vMZ693/containers/70b22332-6c59-4c4b-b2c2-01e043155e32/containers/615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7/termination'
I1029 18:39:46.134325 20697 linux_launcher.cpp:576] Asked to destroy container
70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:46.134374 20697 linux_launcher.cpp:618] Destroying cgroup
'/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32'
I1029 18:39:46.134573 20697 cgroups.cpp:2854] Freezing cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:46.134732 20696 cgroups.cpp:1242] Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32
after 117248ns
I1029 18:39:46.134980 20701 cgroups.cpp:2872] Thawing cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32
I1029 18:39:46.137166 20701 cgroups.cpp:1271] Successfully thawed cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871/70b22332-6c59-4c4b-b2c2-01e043155e32
after 2.150912ms
I1029 18:39:46.203644 20696 containerizer.cpp:3156] Container
70b22332-6c59-4c4b-b2c2-01e043155e32 has exited
E1029 18:39:46.205171 20702 memory.cpp:501] Listening on OOM events failed for
container 70b22332-6c59-4c4b-b2c2-01e043155e32: Event listener is terminating
I1029 18:39:46.206370 20698 provisioner.cpp:652] Ignoring destroy request for
unknown container 70b22332-6c59-4c4b-b2c2-01e043155e32
W1029 18:39:46.206853 20703 containerizer.cpp:2600] Attempted to destroy
unknown container
70b22332-6c59-4c4b-b2c2-01e043155e32.615b98b2-32e0-46e4-9ae9-4a9c48f3fbb7
I1029 18:39:46.210639 597 master.cpp:1137] Master terminating
I1029 18:39:46.210758 20702 hierarchical.cpp:1023] Removed all filters for
agent 68270ce9-2cc9-4146-9122-2c124f69e914-S0
I1029 18:39:46.210780 20702 hierarchical.cpp:900] Removed agent
68270ce9-2cc9-4146-9122-2c124f69e914-S0
I1029 18:39:46.220875 20702 cgroups.cpp:2854] Freezing cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871
I1029 18:39:46.321583 20701 cgroups.cpp:1242] Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871 after
100.668928ms
I1029 18:39:46.321800 20697 cgroups.cpp:2872] Thawing cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871
I1029 18:39:46.321913 20697 cgroups.cpp:1271] Successfully thawed cgroup
/sys/fs/cgroup/freezer/mesos_test_ed8ef195-f82c-4779-a676-9b1510c1d871 after
76032ns
[ FAILED ]
CgroupsIsolatorTest.ROOT_CGROUPS_NestedContainerSpecificCgroupsMount (15553 ms)
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
