Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
1.9.0
-
None
-
None
Description
Observed in an internal CI.
Looks like the TASK_RUNNING update has never reached the framework and, most likely, has never been generated:
[ 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)