You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Gilbert Song (JIRA)" <ji...@apache.org> on 2016/06/21 01:46:57 UTC
[jira] [Created] (MESOS-5670)
MemoryPressureMesosTest.CGROUPS_ROOT_SlaveRecovery is flaky.
Gilbert Song created MESOS-5670:
-----------------------------------
Summary: MemoryPressureMesosTest.CGROUPS_ROOT_SlaveRecovery is flaky.
Key: MESOS-5670
URL: https://issues.apache.org/jira/browse/MESOS-5670
Project: Mesos
Issue Type: Bug
Components: cgroups, tests
Environment: CentOS 6, Debian 8, Ubuntu 15, Ubuntu 16
Reporter: Gilbert Song
Assignee: Gilbert Song
{noformat}
[03:36:29] : [Step 10/10] [ RUN ] MemoryPressureMesosTest.CGROUPS_ROOT_SlaveRecovery
[03:36:29]W: [Step 10/10] I0618 03:36:29.461802 2797 cluster.cpp:155] Creating default 'local' authorizer
[03:36:29]W: [Step 10/10] I0618 03:36:29.469468 2797 leveldb.cpp:174] Opened db in 7.527163ms
[03:36:29]W: [Step 10/10] I0618 03:36:29.470188 2797 leveldb.cpp:181] Compacted db in 699544ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.470206 2797 leveldb.cpp:196] Created db iterator in 4293ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.470211 2797 leveldb.cpp:202] Seeked to beginning of db in 535ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.470216 2797 leveldb.cpp:271] Iterated through 0 keys in the db in 321ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.470230 2797 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[03:36:29]W: [Step 10/10] I0618 03:36:29.470510 2815 recover.cpp:451] Starting replica recovery
[03:36:29]W: [Step 10/10] I0618 03:36:29.470592 2817 recover.cpp:477] Replica is in EMPTY status
[03:36:29]W: [Step 10/10] I0618 03:36:29.471029 2813 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (19800)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.471139 2816 recover.cpp:197] Received a recover response from a replica in EMPTY status
[03:36:29]W: [Step 10/10] I0618 03:36:29.471271 2818 recover.cpp:568] Updating replica status to STARTING
[03:36:29]W: [Step 10/10] I0618 03:36:29.471606 2811 master.cpp:382] Master 6d44b7c1-ac0b-4409-97df-a53fa2e39d09 (ip-172-30-2-29.mesosphere.io) started on 172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.471619 2811 master.cpp:384] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/baXWq5/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/baXWq5/master" --zk_session_timeout="10secs"
[03:36:29]W: [Step 10/10] I0618 03:36:29.471745 2811 master.cpp:434] Master only allowing authenticated frameworks to register
[03:36:29]W: [Step 10/10] I0618 03:36:29.471753 2811 master.cpp:448] Master only allowing authenticated agents to register
[03:36:29]W: [Step 10/10] I0618 03:36:29.471757 2811 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
[03:36:29]W: [Step 10/10] I0618 03:36:29.471761 2811 credentials.hpp:37] Loading credentials for authentication from '/tmp/baXWq5/credentials'
[03:36:29]W: [Step 10/10] I0618 03:36:29.471829 2811 master.cpp:506] Using default 'crammd5' authenticator
[03:36:29]W: [Step 10/10] I0618 03:36:29.471868 2811 master.cpp:578] Using default 'basic' HTTP authenticator
[03:36:29]W: [Step 10/10] I0618 03:36:29.471941 2811 master.cpp:658] Using default 'basic' HTTP framework authenticator
[03:36:29]W: [Step 10/10] I0618 03:36:29.471977 2811 master.cpp:705] Authorization enabled
[03:36:29]W: [Step 10/10] I0618 03:36:29.472034 2817 hierarchical.cpp:142] Initialized hierarchical allocator process
[03:36:29]W: [Step 10/10] I0618 03:36:29.472038 2814 whitelist_watcher.cpp:77] No whitelist given
[03:36:29]W: [Step 10/10] I0618 03:36:29.472506 2811 master.cpp:1969] The newly elected leader is master@172.30.2.29:37328 with id 6d44b7c1-ac0b-4409-97df-a53fa2e39d09
[03:36:29]W: [Step 10/10] I0618 03:36:29.472522 2811 master.cpp:1982] Elected as the leading master!
[03:36:29]W: [Step 10/10] I0618 03:36:29.472527 2811 master.cpp:1669] Recovering from registrar
[03:36:29]W: [Step 10/10] I0618 03:36:29.472573 2812 registrar.cpp:332] Recovering registrar
[03:36:29]W: [Step 10/10] I0618 03:36:29.473511 2816 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.195002ms
[03:36:29]W: [Step 10/10] I0618 03:36:29.473527 2816 replica.cpp:320] Persisted replica status to STARTING
[03:36:29]W: [Step 10/10] I0618 03:36:29.473578 2816 recover.cpp:477] Replica is in STARTING status
[03:36:29]W: [Step 10/10] I0618 03:36:29.473877 2815 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (19803)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.473989 2814 recover.cpp:197] Received a recover response from a replica in STARTING status
[03:36:29]W: [Step 10/10] I0618 03:36:29.474126 2817 recover.cpp:568] Updating replica status to VOTING
[03:36:29]W: [Step 10/10] I0618 03:36:29.474735 2811 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 547332ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.474748 2811 replica.cpp:320] Persisted replica status to VOTING
[03:36:29]W: [Step 10/10] I0618 03:36:29.474783 2811 recover.cpp:582] Successfully joined the Paxos group
[03:36:29]W: [Step 10/10] I0618 03:36:29.474829 2811 recover.cpp:466] Recover process terminated
[03:36:29]W: [Step 10/10] I0618 03:36:29.474969 2818 log.cpp:553] Attempting to start the writer
[03:36:29]W: [Step 10/10] I0618 03:36:29.475361 2811 replica.cpp:493] Replica received implicit promise request from (19804)@172.30.2.29:37328 with proposal 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.475944 2811 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 559444ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.475956 2811 replica.cpp:342] Persisted promised to 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.476215 2815 coordinator.cpp:238] Coordinator attempting to fill missing positions
[03:36:29]W: [Step 10/10] I0618 03:36:29.476660 2816 replica.cpp:388] Replica received explicit promise request from (19805)@172.30.2.29:37328 for position 0 with proposal 2
[03:36:29]W: [Step 10/10] I0618 03:36:29.477262 2816 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 584333ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.477273 2816 replica.cpp:712] Persisted action at 0
[03:36:29]W: [Step 10/10] I0618 03:36:29.477699 2815 replica.cpp:537] Replica received write request for position 0 from (19806)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.477726 2815 leveldb.cpp:436] Reading position from leveldb took 8842ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.478277 2815 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 537361ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.478291 2815 replica.cpp:712] Persisted action at 0
[03:36:29]W: [Step 10/10] I0618 03:36:29.478569 2811 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[03:36:29]W: [Step 10/10] I0618 03:36:29.479132 2811 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 545208ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.479146 2811 replica.cpp:712] Persisted action at 0
[03:36:29]W: [Step 10/10] I0618 03:36:29.479152 2811 replica.cpp:697] Replica learned NOP action at position 0
[03:36:29]W: [Step 10/10] I0618 03:36:29.479317 2814 log.cpp:569] Writer started with ending position 0
[03:36:29]W: [Step 10/10] I0618 03:36:29.479568 2811 leveldb.cpp:436] Reading position from leveldb took 8325ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.479786 2814 registrar.cpp:365] Successfully fetched the registry (0B) in 7.192064ms
[03:36:29]W: [Step 10/10] I0618 03:36:29.479822 2814 registrar.cpp:464] Applied 1 operations in 3018ns; attempting to update the 'registry'
[03:36:29]W: [Step 10/10] I0618 03:36:29.479995 2818 log.cpp:577] Attempting to append 205 bytes to the log
[03:36:29]W: [Step 10/10] I0618 03:36:29.480044 2818 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.480309 2811 replica.cpp:537] Replica received write request for position 1 from (19807)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.480928 2811 leveldb.cpp:341] Persisting action (224 bytes) to leveldb took 596433ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.480942 2811 replica.cpp:712] Persisted action at 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.481148 2815 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[03:36:29]W: [Step 10/10] I0618 03:36:29.481710 2815 leveldb.cpp:341] Persisting action (226 bytes) to leveldb took 545656ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.481722 2815 replica.cpp:712] Persisted action at 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.481727 2815 replica.cpp:697] Replica learned APPEND action at position 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.481958 2816 registrar.cpp:509] Successfully updated the 'registry' in 2.119168ms
[03:36:29]W: [Step 10/10] I0618 03:36:29.482014 2816 registrar.cpp:395] Successfully recovered registrar
[03:36:29]W: [Step 10/10] I0618 03:36:29.482045 2817 log.cpp:596] Attempting to truncate the log to 1
[03:36:29]W: [Step 10/10] I0618 03:36:29.482117 2817 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[03:36:29]W: [Step 10/10] I0618 03:36:29.482166 2816 master.cpp:1777] Recovered 0 agents from the Registry (166B) ; allowing 10mins for agents to re-register
[03:36:29]W: [Step 10/10] I0618 03:36:29.482177 2817 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[03:36:29]W: [Step 10/10] I0618 03:36:29.482404 2817 replica.cpp:537] Replica received write request for position 2 from (19808)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.482975 2817 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 552763ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.482986 2817 replica.cpp:712] Persisted action at 2
[03:36:29]W: [Step 10/10] I0618 03:36:29.483301 2813 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[03:36:29]W: [Step 10/10] I0618 03:36:29.483870 2813 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 547529ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.483896 2813 leveldb.cpp:399] Deleting ~1 keys from leveldb took 12161ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.483904 2813 replica.cpp:712] Persisted action at 2
[03:36:29]W: [Step 10/10] I0618 03:36:29.483911 2813 replica.cpp:697] Replica learned TRUNCATE action at position 2
[03:36:29]W: [Step 10/10] I0618 03:36:29.492995 2797 containerizer.cpp:201] Using isolation: cgroups/mem,filesystem/posix,network/cni
[03:36:29]W: [Step 10/10] I0618 03:36:29.496548 2797 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[03:36:29]W: [Step 10/10] I0618 03:36:29.503572 2797 cluster.cpp:432] Creating default 'local' authorizer
[03:36:29]W: [Step 10/10] I0618 03:36:29.503936 2817 slave.cpp:203] Agent started on 488)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.503952 2817 slave.cpp:204] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="cgroups/mem" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL"
[03:36:29]W: [Step 10/10] I0618 03:36:29.504148 2817 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/credential'
[03:36:29]W: [Step 10/10] I0618 03:36:29.504189 2817 slave.cpp:341] Agent using credential for: test-principal
[03:36:29]W: [Step 10/10] I0618 03:36:29.504199 2817 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/http_credentials'
[03:36:29]W: [Step 10/10] I0618 03:36:29.504245 2817 slave.cpp:393] Using default 'basic' HTTP authenticator
[03:36:29]W: [Step 10/10] I0618 03:36:29.504410 2797 sched.cpp:224] Version: 1.0.0
[03:36:29]W: [Step 10/10] I0618 03:36:29.504416 2817 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[03:36:29]W: [Step 10/10] Trying semicolon-delimited string format instead
[03:36:29]W: [Step 10/10] I0618 03:36:29.504580 2818 sched.cpp:328] New master detected at master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.504613 2818 sched.cpp:394] Authenticating with master master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.504622 2818 sched.cpp:401] Using default CRAM-MD5 authenticatee
[03:36:29]W: [Step 10/10] I0618 03:36:29.504649 2817 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[03:36:29]W: [Step 10/10] I0618 03:36:29.504673 2817 slave.cpp:600] Agent attributes: [ ]
[03:36:29]W: [Step 10/10] I0618 03:36:29.504678 2817 slave.cpp:605] Agent hostname: ip-172-30-2-29.mesosphere.io
[03:36:29]W: [Step 10/10] I0618 03:36:29.504703 2816 authenticatee.cpp:121] Creating new client SASL connection
[03:36:29]W: [Step 10/10] I0618 03:36:29.504830 2818 master.cpp:5943] Authenticating scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.504887 2816 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(991)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.504982 2811 authenticator.cpp:98] Creating new server SASL connection
[03:36:29]W: [Step 10/10] I0618 03:36:29.505004 2816 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta'
[03:36:29]W: [Step 10/10] I0618 03:36:29.505105 2813 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[03:36:29]W: [Step 10/10] I0618 03:36:29.505131 2813 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[03:36:29]W: [Step 10/10] I0618 03:36:29.505138 2818 status_update_manager.cpp:200] Recovering status update manager
[03:36:29]W: [Step 10/10] I0618 03:36:29.505167 2813 authenticator.cpp:204] Received SASL authentication start
[03:36:29]W: [Step 10/10] I0618 03:36:29.505200 2813 authenticator.cpp:326] Authentication requires more steps
[03:36:29]W: [Step 10/10] I0618 03:36:29.505200 2814 containerizer.cpp:514] Recovering containerizer
[03:36:29]W: [Step 10/10] I0618 03:36:29.505241 2813 authenticatee.cpp:259] Received SASL authentication step
[03:36:29]W: [Step 10/10] I0618 03:36:29.505300 2812 authenticator.cpp:232] Received SASL authentication step
[03:36:29]W: [Step 10/10] I0618 03:36:29.505317 2812 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-29.mesosphere.io' server FQDN: 'ip-172-30-2-29.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[03:36:29]W: [Step 10/10] I0618 03:36:29.505323 2812 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[03:36:29]W: [Step 10/10] I0618 03:36:29.505331 2812 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[03:36:29]W: [Step 10/10] I0618 03:36:29.505337 2812 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-29.mesosphere.io' server FQDN: 'ip-172-30-2-29.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[03:36:29]W: [Step 10/10] I0618 03:36:29.505342 2812 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[03:36:29]W: [Step 10/10] I0618 03:36:29.505347 2812 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[03:36:29]W: [Step 10/10] I0618 03:36:29.505355 2812 authenticator.cpp:318] Authentication success
[03:36:29]W: [Step 10/10] I0618 03:36:29.505399 2813 authenticatee.cpp:299] Authentication success
[03:36:29]W: [Step 10/10] I0618 03:36:29.505421 2811 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(991)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.505436 2812 master.cpp:5973] Successfully authenticated principal 'test-principal' at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.505534 2816 sched.cpp:484] Successfully authenticated with master master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.505553 2816 sched.cpp:800] Sending SUBSCRIBE call to master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.505591 2816 sched.cpp:833] Will retry registration in 11.319315ms if necessary
[03:36:29]W: [Step 10/10] I0618 03:36:29.505672 2815 master.cpp:2539] Received SUBSCRIBE call for framework 'default' at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.505702 2815 master.cpp:2008] Authorizing framework principal 'test-principal' to receive offers for role '*'
[03:36:29]W: [Step 10/10] I0618 03:36:29.505854 2818 master.cpp:2615] Subscribing framework default with checkpointing enabled and capabilities [ ]
[03:36:29]W: [Step 10/10] I0618 03:36:29.506031 2818 sched.cpp:723] Framework registered with 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.506050 2816 hierarchical.cpp:264] Added framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.506072 2816 hierarchical.cpp:1488] No allocations performed
[03:36:29]W: [Step 10/10] I0618 03:36:29.506073 2818 sched.cpp:737] Scheduler::registered took 28711ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.506093 2816 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:29]W: [Step 10/10] I0618 03:36:29.506126 2816 hierarchical.cpp:1139] Performed allocation for 0 agents in 59667ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.506428 2818 provisioner.cpp:253] Provisioner recovery complete
[03:36:29]W: [Step 10/10] I0618 03:36:29.506570 2815 slave.cpp:4845] Finished recovery
[03:36:29]W: [Step 10/10] I0618 03:36:29.506747 2815 slave.cpp:5017] Querying resource estimator for oversubscribable resources
[03:36:29]W: [Step 10/10] I0618 03:36:29.506878 2813 slave.cpp:967] New master detected at master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.506886 2814 status_update_manager.cpp:174] Pausing sending status updates
[03:36:29]W: [Step 10/10] I0618 03:36:29.506903 2813 slave.cpp:1029] Authenticating with master master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.506924 2813 slave.cpp:1040] Using default CRAM-MD5 authenticatee
[03:36:29]W: [Step 10/10] I0618 03:36:29.506976 2813 slave.cpp:1002] Detecting new master
[03:36:29]W: [Step 10/10] I0618 03:36:29.506989 2816 authenticatee.cpp:121] Creating new client SASL connection
[03:36:29]W: [Step 10/10] I0618 03:36:29.507069 2813 slave.cpp:5031] Received oversubscribable resources from the resource estimator
[03:36:29]W: [Step 10/10] I0618 03:36:29.507145 2815 master.cpp:5943] Authenticating slave(488)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.507202 2811 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(992)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.507264 2817 authenticator.cpp:98] Creating new server SASL connection
[03:36:29]W: [Step 10/10] I0618 03:36:29.507374 2817 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[03:36:29]W: [Step 10/10] I0618 03:36:29.507387 2817 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[03:36:29]W: [Step 10/10] I0618 03:36:29.507433 2813 authenticator.cpp:204] Received SASL authentication start
[03:36:29]W: [Step 10/10] I0618 03:36:29.507467 2813 authenticator.cpp:326] Authentication requires more steps
[03:36:29]W: [Step 10/10] I0618 03:36:29.507511 2813 authenticatee.cpp:259] Received SASL authentication step
[03:36:29]W: [Step 10/10] I0618 03:36:29.507578 2811 authenticator.cpp:232] Received SASL authentication step
[03:36:29]W: [Step 10/10] I0618 03:36:29.507597 2811 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-29.mesosphere.io' server FQDN: 'ip-172-30-2-29.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[03:36:29]W: [Step 10/10] I0618 03:36:29.507606 2811 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[03:36:29]W: [Step 10/10] I0618 03:36:29.507617 2811 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[03:36:29]W: [Step 10/10] I0618 03:36:29.507629 2811 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-29.mesosphere.io' server FQDN: 'ip-172-30-2-29.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[03:36:29]W: [Step 10/10] I0618 03:36:29.507640 2811 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[03:36:29]W: [Step 10/10] I0618 03:36:29.507648 2811 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[03:36:29]W: [Step 10/10] I0618 03:36:29.507686 2811 authenticator.cpp:318] Authentication success
[03:36:29]W: [Step 10/10] I0618 03:36:29.507750 2817 authenticatee.cpp:299] Authentication success
[03:36:29]W: [Step 10/10] I0618 03:36:29.507766 2811 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(992)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.507786 2813 master.cpp:5973] Successfully authenticated principal 'test-principal' at slave(488)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.507863 2817 slave.cpp:1108] Successfully authenticated with master master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.507910 2817 slave.cpp:1511] Will retry registration in 10.588836ms if necessary
[03:36:29]W: [Step 10/10] I0618 03:36:29.507966 2812 master.cpp:4653] Registering agent at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io) with id 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0
[03:36:29]W: [Step 10/10] I0618 03:36:29.508059 2817 registrar.cpp:464] Applied 1 operations in 13429ns; attempting to update the 'registry'
[03:36:29]W: [Step 10/10] I0618 03:36:29.508244 2812 log.cpp:577] Attempting to append 390 bytes to the log
[03:36:29]W: [Step 10/10] I0618 03:36:29.508296 2817 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[03:36:29]W: [Step 10/10] I0618 03:36:29.508546 2815 replica.cpp:537] Replica received write request for position 3 from (19831)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.509158 2815 leveldb.cpp:341] Persisting action (409 bytes) to leveldb took 589901ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.509171 2815 replica.cpp:712] Persisted action at 3
[03:36:29]W: [Step 10/10] I0618 03:36:29.509403 2815 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[03:36:29]W: [Step 10/10] I0618 03:36:29.509980 2815 leveldb.cpp:341] Persisting action (411 bytes) to leveldb took 558737ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.509992 2815 replica.cpp:712] Persisted action at 3
[03:36:29]W: [Step 10/10] I0618 03:36:29.509999 2815 replica.cpp:697] Replica learned APPEND action at position 3
[03:36:29]W: [Step 10/10] I0618 03:36:29.510262 2818 registrar.cpp:509] Successfully updated the 'registry' in 2.178048ms
[03:36:29]W: [Step 10/10] I0618 03:36:29.510313 2811 log.cpp:596] Attempting to truncate the log to 3
[03:36:29]W: [Step 10/10] I0618 03:36:29.510375 2817 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[03:36:29]W: [Step 10/10] I0618 03:36:29.510486 2818 slave.cpp:3747] Received ping from slave-observer(447)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.510519 2816 master.cpp:4721] Registered agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[03:36:29]W: [Step 10/10] I0618 03:36:29.510540 2818 slave.cpp:1152] Registered with master master@172.30.2.29:37328; given agent ID 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0
[03:36:29]W: [Step 10/10] I0618 03:36:29.510577 2818 fetcher.cpp:86] Clearing fetcher cache
[03:36:29]W: [Step 10/10] I0618 03:36:29.510577 2815 hierarchical.cpp:473] Added agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 (ip-172-30-2-29.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[03:36:29]W: [Step 10/10] I0618 03:36:29.510639 2811 replica.cpp:537] Replica received write request for position 4 from (19832)@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.510658 2816 status_update_manager.cpp:181] Resuming sending status updates
[03:36:29]W: [Step 10/10] I0618 03:36:29.510730 2815 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:29]W: [Step 10/10] I0618 03:36:29.510747 2815 hierarchical.cpp:1162] Performed allocation for agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 in 127305ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.510766 2818 slave.cpp:1175] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/slave.info'
[03:36:29]W: [Step 10/10] I0618 03:36:29.510848 2816 master.cpp:5772] Sending 1 offers to framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.510892 2818 slave.cpp:1212] Forwarding total oversubscribed resources
[03:36:29]W: [Step 10/10] I0618 03:36:29.510956 2818 master.cpp:5066] Received update of agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io) with total oversubscribed resources
[03:36:29]W: [Step 10/10] I0618 03:36:29.510987 2817 sched.cpp:897] Scheduler::resourceOffers took 30391ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.511080 2816 hierarchical.cpp:531] Agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 (ip-172-30-2-29.mesosphere.io) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
[03:36:29]W: [Step 10/10] I0618 03:36:29.511124 2816 hierarchical.cpp:1488] No allocations performed
[03:36:29]W: [Step 10/10] I0618 03:36:29.511132 2797 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:256;disk:1024
[03:36:29]W: [Step 10/10] Trying semicolon-delimited string format instead
[03:36:29]W: [Step 10/10] I0618 03:36:29.511133 2816 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:29]W: [Step 10/10] I0618 03:36:29.511167 2816 hierarchical.cpp:1162] Performed allocation for agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 in 57933ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.511201 2811 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 542938ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.511214 2811 replica.cpp:712] Persisted action at 4
[03:36:29]W: [Step 10/10] I0618 03:36:29.511431 2818 master.cpp:3457] Processing ACCEPT call for offers: [ 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-O0 ] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io) for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.511461 2818 master.cpp:3095] Authorizing framework principal 'test-principal' to launch task e9fcbad2-73bf-409e-9f71-023b826b5286
[03:36:29]W: [Step 10/10] I0618 03:36:29.511560 2816 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[03:36:29]W: [Step 10/10] I0618 03:36:29.511827 2811 master.hpp:177] Adding task e9fcbad2-73bf-409e-9f71-023b826b5286 with resources cpus(*):1; mem(*):256; disk(*):1024 on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 (ip-172-30-2-29.mesosphere.io)
[03:36:29]W: [Step 10/10] I0618 03:36:29.511859 2811 master.cpp:3946] Launching task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328 with resources cpus(*):1; mem(*):256; disk(*):1024 on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io)
[03:36:29]W: [Step 10/10] I0618 03:36:29.511968 2814 slave.cpp:1551] Got assigned task e9fcbad2-73bf-409e-9f71-023b826b5286 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.511984 2815 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):768; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):256; disk(*):1024) on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 from framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.512009 2815 hierarchical.cpp:928] Framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 filtered agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for 5secs
[03:36:29]W: [Step 10/10] I0618 03:36:29.512022 2814 slave.cpp:5654] Checkpointing FrameworkInfo to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/framework.info'
[03:36:29]W: [Step 10/10] I0618 03:36:29.512127 2816 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 544409ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.512138 2814 slave.cpp:5665] Checkpointing framework pid 'scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328' to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/framework.pid'
[03:36:29]W: [Step 10/10] I0618 03:36:29.512153 2816 leveldb.cpp:399] Deleting ~2 keys from leveldb took 13134ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.512162 2816 replica.cpp:712] Persisted action at 4
[03:36:29]W: [Step 10/10] I0618 03:36:29.512167 2816 replica.cpp:697] Replica learned TRUNCATE action at position 4
[03:36:29]W: [Step 10/10] I0618 03:36:29.512245 2814 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[03:36:29]W: [Step 10/10] Trying semicolon-delimited string format instead
[03:36:29]W: [Step 10/10] I0618 03:36:29.512377 2814 slave.cpp:1670] Launching task e9fcbad2-73bf-409e-9f71-023b826b5286 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.512408 2814 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[03:36:29]W: [Step 10/10] Trying semicolon-delimited string format instead
[03:36:29]W: [Step 10/10] I0618 03:36:29.512596 2814 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82' to user 'root'
[03:36:29]W: [Step 10/10] I0618 03:36:29.517411 2814 slave.cpp:6136] Checkpointing ExecutorInfo to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/executor.info'
[03:36:29]W: [Step 10/10] I0618 03:36:29.517659 2814 slave.cpp:5734] Launching executor e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82'
[03:36:29]W: [Step 10/10] I0618 03:36:29.517853 2814 slave.cpp:6159] Checkpointing TaskInfo to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82/tasks/e9fcbad2-73bf-409e-9f71-023b826b5286/task.info'
[03:36:29]W: [Step 10/10] I0618 03:36:29.517861 2818 containerizer.cpp:773] Starting container '8a5ba23c-d1d2-4708-ab2f-40a6c269ef82' for executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework '6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000'
[03:36:29]W: [Step 10/10] I0618 03:36:29.518013 2814 slave.cpp:1896] Queuing task 'e9fcbad2-73bf-409e-9f71-023b826b5286' for executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.518056 2814 slave.cpp:920] Successfully attached file '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82'
[03:36:29]W: [Step 10/10] I0618 03:36:29.519455 2817 mem.cpp:602] Started listening for OOM events for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.519815 2817 mem.cpp:722] Started listening on low memory pressure events for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.520133 2817 mem.cpp:722] Started listening on medium memory pressure events for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.520447 2817 mem.cpp:722] Started listening on critical memory pressure events for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.520769 2817 mem.cpp:353] Updated 'memory.soft_limit_in_bytes' to 288MB for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.521339 2817 mem.cpp:388] Updated 'memory.limit_in_bytes' to 288MB for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.521926 2816 containerizer.cpp:1267] Launching 'mesos-containerizer' with flags '--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --commands="{"commands":[]}" --help="false" --pipe_read="119" --pipe_write="120" --sandbox="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82" --user="root"'
[03:36:29]W: [Step 10/10] I0618 03:36:29.521984 2816 linux_launcher.cpp:281] Cloning child process with flags =
[03:36:29]W: [Step 10/10] I0618 03:36:29.544052 2816 containerizer.cpp:1302] Checkpointing executor's forked pid 20673 to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82/pids/forked.pid'
[03:36:29]W: [Step 10/10] WARNING: Logging before InitGoogleLogging() is written to STDERR
[03:36:29]W: [Step 10/10] I0618 03:36:29.603862 20687 process.cpp:1060] libprocess is initialized on 172.30.2.29:44617 with 8 worker threads
[03:36:29]W: [Step 10/10] I0618 03:36:29.605692 20687 logging.cpp:199] Logging to STDERR
[03:36:29]W: [Step 10/10] I0618 03:36:29.606240 20687 exec.cpp:161] Version: 1.0.0
[03:36:29]W: [Step 10/10] I0618 03:36:29.606302 20704 exec.cpp:211] Executor started at: executor(1)@172.30.2.29:44617 with pid 20687
[03:36:29]W: [Step 10/10] I0618 03:36:29.606724 2814 slave.cpp:2884] Got registration for executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 from executor(1)@172.30.2.29:44617
[03:36:29]W: [Step 10/10] I0618 03:36:29.606885 2814 slave.cpp:2970] Checkpointing executor pid 'executor(1)@172.30.2.29:44617' to '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82/pids/libprocess.pid'
[03:36:29]W: [Step 10/10] I0618 03:36:29.607306 20703 exec.cpp:236] Executor registered on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0
[03:36:29]W: [Step 10/10] I0618 03:36:29.607925 2815 mem.cpp:353] Updated 'memory.soft_limit_in_bytes' to 288MB for container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:29]W: [Step 10/10] I0618 03:36:29.608141 20703 exec.cpp:248] Executor::registered took 89576ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.608538 2816 slave.cpp:2061] Sending queued task 'e9fcbad2-73bf-409e-9f71-023b826b5286' to executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 at executor(1)@172.30.2.29:44617
[03:36:29]W: [Step 10/10] I0618 03:36:29.608767 20705 exec.cpp:323] Executor asked to run task 'e9fcbad2-73bf-409e-9f71-023b826b5286'
[03:36:29]W: [Step 10/10] I0618 03:36:29.608811 20705 exec.cpp:332] Executor::launchTask took 26475ns
[03:36:29] : [Step 10/10] Received SUBSCRIBED event
[03:36:29] : [Step 10/10] Subscribed executor on ip-172-30-2-29.mesosphere.io
[03:36:29] : [Step 10/10] Received LAUNCH event
[03:36:29] : [Step 10/10] Starting task e9fcbad2-73bf-409e-9f71-023b826b5286
[03:36:29] : [Step 10/10] Forked command at 20710
[03:36:29] : [Step 10/10] sh -c 'while true; do dd count=512 bs=1M if=/dev/zero of=./temp; done'
[03:36:29]W: [Step 10/10] I0618 03:36:29.611716 20705 exec.cpp:546] Executor sending status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.611974 2815 slave.cpp:3267] Handling status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 from executor(1)@172.30.2.29:44617
[03:36:29]W: [Step 10/10] I0618 03:36:29.612499 2818 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.612527 2818 status_update_manager.cpp:497] Creating StatusUpdate stream for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.612751 2818 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.725725 2818 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 to the agent
[03:36:29]W: [Step 10/10] I0618 03:36:29.725908 2817 slave.cpp:3665] Forwarding the update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 to master@172.30.2.29:37328
[03:36:29]W: [Step 10/10] I0618 03:36:29.725999 2817 slave.cpp:3559] Status update manager successfully handled status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.726016 2817 slave.cpp:3575] Sending acknowledgement for status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 to executor(1)@172.30.2.29:44617
[03:36:29]W: [Step 10/10] I0618 03:36:29.726124 2813 master.cpp:5211] Status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 from agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io)
[03:36:29]W: [Step 10/10] I0618 03:36:29.726157 2813 master.cpp:5259] Forwarding status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.726238 2813 master.cpp:6871] Updating the state of task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
[03:36:29]W: [Step 10/10] I0618 03:36:29.726300 20701 exec.cpp:369] Executor received status update acknowledgement bea75e2e-9827-4410-9864-288f29c0a618 for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.726363 2818 sched.cpp:1005] Scheduler::statusUpdate took 77055ns
[03:36:29]W: [Step 10/10] I0618 03:36:29.726517 2814 master.cpp:4365] Processing ACKNOWLEDGE call bea75e2e-9827-4410-9864-288f29c0a618 for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328 on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0
[03:36:29]W: [Step 10/10] I0618 03:36:29.726757 2816 status_update_manager.cpp:392] Received status update acknowledgement (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:29]W: [Step 10/10] I0618 03:36:29.726812 2816 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:30]W: [Step 10/10] I0618 03:36:30.472790 2817 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):768; ports(*):[31000-32000] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:30]W: [Step 10/10] I0618 03:36:30.472841 2817 hierarchical.cpp:1488] No allocations performed
[03:36:30]W: [Step 10/10] I0618 03:36:30.472847 2817 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:30]W: [Step 10/10] I0618 03:36:30.472864 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 181038ns
[03:36:31]W: [Step 10/10] I0618 03:36:31.474026 2814 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):768; ports(*):[31000-32000] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:31]W: [Step 10/10] I0618 03:36:31.474076 2814 hierarchical.cpp:1488] No allocations performed
[03:36:31]W: [Step 10/10] I0618 03:36:31.474083 2814 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:31]W: [Step 10/10] I0618 03:36:31.474097 2814 hierarchical.cpp:1139] Performed allocation for 1 agents in 180187ns
[03:36:32]W: [Step 10/10] I0618 03:36:32.475332 2817 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):768; ports(*):[31000-32000] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:32]W: [Step 10/10] I0618 03:36:32.475383 2817 hierarchical.cpp:1488] No allocations performed
[03:36:32]W: [Step 10/10] I0618 03:36:32.475389 2817 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:32]W: [Step 10/10] I0618 03:36:32.475402 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 176560ns
[03:36:33]W: [Step 10/10] I0618 03:36:33.476011 2814 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):768; ports(*):[31000-32000] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:33]W: [Step 10/10] I0618 03:36:33.476059 2814 hierarchical.cpp:1488] No allocations performed
[03:36:33]W: [Step 10/10] I0618 03:36:33.476066 2814 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:33]W: [Step 10/10] I0618 03:36:33.476080 2814 hierarchical.cpp:1139] Performed allocation for 1 agents in 194002ns
[03:36:33]W: [Step 10/10] 512+0 records in
[03:36:33]W: [Step 10/10] 512+0 records out
[03:36:33]W: [Step 10/10] 536870912 bytes (537 MB, 512 MiB) copied, 4.23412 s, 127 MB/s
[03:36:34]W: [Step 10/10] I0618 03:36:34.477355 2814 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):768; ports(*):[31000-32000] on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:34]W: [Step 10/10] I0618 03:36:34.477406 2814 hierarchical.cpp:1488] No allocations performed
[03:36:34]W: [Step 10/10] I0618 03:36:34.477413 2814 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:34]W: [Step 10/10] I0618 03:36:34.477427 2814 hierarchical.cpp:1139] Performed allocation for 1 agents in 184403ns
[03:36:35]W: [Step 10/10] I0618 03:36:35.477726 2811 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:35]W: [Step 10/10] I0618 03:36:35.477774 2811 hierarchical.cpp:1139] Performed allocation for 1 agents in 202326ns
[03:36:35]W: [Step 10/10] I0618 03:36:35.477824 2818 master.cpp:5772] Sending 1 offers to framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:35]W: [Step 10/10] I0618 03:36:35.477948 2818 sched.cpp:897] Scheduler::resourceOffers took 9712ns
[03:36:36]W: [Step 10/10] I0618 03:36:36.478219 2814 hierarchical.cpp:1488] No allocations performed
[03:36:36]W: [Step 10/10] I0618 03:36:36.478235 2814 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:36]W: [Step 10/10] I0618 03:36:36.478245 2814 hierarchical.cpp:1139] Performed allocation for 1 agents in 47187ns
[03:36:37]W: [Step 10/10] I0618 03:36:37.478663 2811 hierarchical.cpp:1488] No allocations performed
[03:36:37]W: [Step 10/10] I0618 03:36:37.478678 2811 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:37]W: [Step 10/10] I0618 03:36:37.478693 2811 hierarchical.cpp:1139] Performed allocation for 1 agents in 45629ns
[03:36:38]W: [Step 10/10] I0618 03:36:38.479481 2817 hierarchical.cpp:1488] No allocations performed
[03:36:38]W: [Step 10/10] I0618 03:36:38.479516 2817 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:38]W: [Step 10/10] I0618 03:36:38.479532 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 98966ns
[03:36:39]W: [Step 10/10] I0618 03:36:39.480494 2813 hierarchical.cpp:1488] No allocations performed
[03:36:39]W: [Step 10/10] I0618 03:36:39.480526 2813 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:39]W: [Step 10/10] I0618 03:36:39.480543 2813 hierarchical.cpp:1139] Performed allocation for 1 agents in 87017ns
[03:36:40]W: [Step 10/10] I0618 03:36:40.481472 2812 hierarchical.cpp:1488] No allocations performed
[03:36:40]W: [Step 10/10] I0618 03:36:40.481504 2812 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:40]W: [Step 10/10] I0618 03:36:40.481519 2812 hierarchical.cpp:1139] Performed allocation for 1 agents in 122806ns
[03:36:41]W: [Step 10/10] I0618 03:36:41.482342 2813 hierarchical.cpp:1488] No allocations performed
[03:36:41]W: [Step 10/10] I0618 03:36:41.482378 2813 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:41]W: [Step 10/10] I0618 03:36:41.482393 2813 hierarchical.cpp:1139] Performed allocation for 1 agents in 98739ns
[03:36:42]W: [Step 10/10] I0618 03:36:42.483055 2817 hierarchical.cpp:1488] No allocations performed
[03:36:42]W: [Step 10/10] I0618 03:36:42.483083 2817 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:42]W: [Step 10/10] I0618 03:36:42.483095 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 73620ns
[03:36:43]W: [Step 10/10] I0618 03:36:43.483800 2811 hierarchical.cpp:1488] No allocations performed
[03:36:43]W: [Step 10/10] I0618 03:36:43.483837 2811 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:43]W: [Step 10/10] I0618 03:36:43.483853 2811 hierarchical.cpp:1139] Performed allocation for 1 agents in 103486ns
[03:36:44]W: [Step 10/10] I0618 03:36:44.484480 2818 hierarchical.cpp:1488] No allocations performed
[03:36:44]W: [Step 10/10] I0618 03:36:44.484508 2818 hierarchical.cpp:1583] No inverse offers to send out!
[03:36:44]W: [Step 10/10] I0618 03:36:44.484522 2818 hierarchical.cpp:1139] Performed allocation for 1 agents in 76447ns
[03:36:44]W: [Step 10/10] I0618 03:36:44.507843 2815 slave.cpp:5017] Querying resource estimator for oversubscribable resources
[03:36:44]W: [Step 10/10] I0618 03:36:44.507937 2815 slave.cpp:5031] Received oversubscribable resources from the resource estimator
[03:36:44]W: [Step 10/10] I0618 03:36:44.511128 2812 slave.cpp:3747] Received ping from slave-observer(447)@172.30.2.29:37328
[03:36:44] : [Step 10/10] ../../src/tests/containerizer/memory_pressure_tests.cpp:263: Failure
[03:36:44] : [Step 10/10] Failed to wait 15secs for _statusUpdateAcknowledgement
[03:36:44]W: [Step 10/10] I0618 03:36:44.727337 2815 master.cpp:1406] Framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328 disconnected
[03:36:44]W: [Step 10/10] I0618 03:36:44.727363 2815 master.cpp:2840] Disconnecting framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.727396 2815 master.cpp:2864] Deactivating framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.727478 2814 hierarchical.cpp:375] Deactivated framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:44]W: [Step 10/10] W0618 03:36:44.727489 2815 master.hpp:1967] Master attempted to send message to disconnected framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.727519 2815 master.cpp:1419] Giving framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328 0ns to failover
[03:36:44]W: [Step 10/10] I0618 03:36:44.727556 2814 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):768; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):256; disk(*):1024) on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 from framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:44]W: [Step 10/10] I0618 03:36:44.727741 2814 containerizer.cpp:1576] Destroying container '8a5ba23c-d1d2-4708-ab2f-40a6c269ef82'
[03:36:44]W: [Step 10/10] I0618 03:36:44.728740 2813 master.cpp:5624] Framework failover timeout, removing framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.728765 2813 master.cpp:6354] Removing framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (default) at scheduler-3e992438-052b-45f0-af6a-851091145739@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.728817 2813 master.cpp:6871] Updating the state of task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
[03:36:44]W: [Step 10/10] I0618 03:36:44.728827 2817 slave.cpp:2274] Asked to shut down framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 by master@172.30.2.29:37328
[03:36:44]W: [Step 10/10] I0618 03:36:44.728853 2817 slave.cpp:2299] Shutting down framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:44]W: [Step 10/10] I0618 03:36:44.728869 2817 slave.cpp:4470] Shutting down executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 at executor(1)@172.30.2.29:44617
[03:36:44]W: [Step 10/10] I0618 03:36:44.728896 2811 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:44]W: [Step 10/10] I0618 03:36:44.728937 2815 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):256; disk(*):1024 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 from framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:44] : [Step 10/10] Received SHUTDOWN event
[03:36:44] : [Step 10/10] Shutting down
[03:36:44]W: [Step 10/10] I0618 03:36:44.728950 2813 master.cpp:6937] Removing task e9fcbad2-73bf-409e-9f71-023b826b5286 with resources cpus(*):1; mem(*):256; disk(*):1024 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 on agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io)
[03:36:44] : [Step 10/10] Sending SIGTERM to process tree at pid 20710
[03:36:44]W: [Step 10/10] I0618 03:36:44.729131 20707 exec.cpp:410] Executor asked to shutdown
[03:36:44]W: [Step 10/10] I0618 03:36:44.729141 2815 hierarchical.cpp:326] Removed framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:44]W: [Step 10/10] I0618 03:36:44.729179 20707 exec.cpp:425] Executor::shutdown took 6153ns
[03:36:44]W: [Step 10/10] I0618 03:36:44.729199 20707 exec.cpp:92] Scheduling shutdown of the executor in 5secs
[03:36:45]W: [Step 10/10] I0618 03:36:45.485015 2818 hierarchical.cpp:1488] No allocations performed
[03:36:45]W: [Step 10/10] I0618 03:36:45.485038 2818 hierarchical.cpp:1139] Performed allocation for 1 agents in 47043ns
[03:36:46]W: [Step 10/10] I0618 03:36:46.485332 2811 hierarchical.cpp:1488] No allocations performed
[03:36:46]W: [Step 10/10] I0618 03:36:46.485350 2811 hierarchical.cpp:1139] Performed allocation for 1 agents in 33542ns
[03:36:47]W: [Step 10/10] I0618 03:36:47.486548 2817 hierarchical.cpp:1488] No allocations performed
[03:36:47]W: [Step 10/10] I0618 03:36:47.486588 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 84621ns
[03:36:48]W: [Step 10/10] I0618 03:36:48.487707 2813 hierarchical.cpp:1488] No allocations performed
[03:36:48]W: [Step 10/10] I0618 03:36:48.487751 2813 hierarchical.cpp:1139] Performed allocation for 1 agents in 83039ns
[03:36:49]W: [Step 10/10] I0618 03:36:49.488706 2812 hierarchical.cpp:1488] No allocations performed
[03:36:49]W: [Step 10/10] I0618 03:36:49.488745 2812 hierarchical.cpp:1139] Performed allocation for 1 agents in 78192ns
[03:36:49]W: [Step 10/10] I0618 03:36:49.729018 2811 slave.cpp:4543] Killing executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 at executor(1)@172.30.2.29:44617
[03:36:50]W: [Step 10/10] I0618 03:36:50.489168 2817 hierarchical.cpp:1488] No allocations performed
[03:36:50]W: [Step 10/10] I0618 03:36:50.489207 2817 hierarchical.cpp:1139] Performed allocation for 1 agents in 87236ns
[03:36:51]W: [Step 10/10] I0618 03:36:51.369570 2818 slave.cpp:2653] Status update manager successfully handled status update acknowledgement (UUID: bea75e2e-9827-4410-9864-288f29c0a618) for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:51]W: [Step 10/10] I0618 03:36:51.430644 2813 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82 after 6.70171904secs
[03:36:51]W: [Step 10/10] I0618 03:36:51.431812 2818 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:51]W: [Step 10/10] I0618 03:36:51.432981 2817 cgroups.cpp:1438] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82 after 1.140992ms
[03:36:51]W: [Step 10/10] I0618 03:36:51.433709 2816 slave.cpp:3793] executor(1)@172.30.2.29:44617 exited
[03:36:51]W: [Step 10/10] I0618 03:36:51.443989 2813 containerizer.cpp:1812] Executor for container '8a5ba23c-d1d2-4708-ab2f-40a6c269ef82' has exited
[03:36:51]W: [Step 10/10] I0618 03:36:51.446597 2818 provisioner.cpp:411] Ignoring destroy request for unknown container 8a5ba23c-d1d2-4708-ab2f-40a6c269ef82
[03:36:51]W: [Step 10/10] I0618 03:36:51.446734 2813 slave.cpp:4152] Executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 terminated with signal Killed
[03:36:51]W: [Step 10/10] I0618 03:36:51.446758 2813 slave.cpp:4256] Cleaning up executor 'e9fcbad2-73bf-409e-9f71-023b826b5286' of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000 at executor(1)@172.30.2.29:44617
[03:36:51]W: [Step 10/10] I0618 03:36:51.446943 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82' for gc 6.99999482767407days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447018 2813 slave.cpp:4344] Cleaning up framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:51]W: [Step 10/10] I0618 03:36:51.447038 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286' for gc 6.9999948270963days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447082 2816 status_update_manager.cpp:282] Closing status update streams for framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:51]W: [Step 10/10] I0618 03:36:51.447098 2816 status_update_manager.cpp:528] Cleaning up status update stream for task e9fcbad2-73bf-409e-9f71-023b826b5286 of framework 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000
[03:36:51]W: [Step 10/10] I0618 03:36:51.447100 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286/runs/8a5ba23c-d1d2-4708-ab2f-40a6c269ef82' for gc 6.99999482669037days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447103 2813 slave.cpp:839] Agent terminating
[03:36:51]W: [Step 10/10] I0618 03:36:51.447149 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000/executors/e9fcbad2-73bf-409e-9f71-023b826b5286' for gc 6.99999482630815days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447190 2816 master.cpp:1367] Agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io) disconnected
[03:36:51]W: [Step 10/10] I0618 03:36:51.447209 2816 master.cpp:2899] Disconnecting agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io)
[03:36:51]W: [Step 10/10] I0618 03:36:51.447211 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000' for gc 6.99999482555556days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447237 2816 master.cpp:2918] Deactivating agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 at slave(488)@172.30.2.29:37328 (ip-172-30-2-29.mesosphere.io)
[03:36:51]W: [Step 10/10] I0618 03:36:51.447254 2812 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_SlaveRecovery_MBzwwL/meta/slaves/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0/frameworks/6d44b7c1-ac0b-4409-97df-a53fa2e39d09-0000' for gc 6.99999482534815days in the future
[03:36:51]W: [Step 10/10] I0618 03:36:51.447300 2816 hierarchical.cpp:560] Agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0 deactivated
[03:36:51]W: [Step 10/10] I0618 03:36:51.448766 2797 master.cpp:1214] Master terminating
[03:36:51]W: [Step 10/10] I0618 03:36:51.448875 2814 hierarchical.cpp:505] Removed agent 6d44b7c1-ac0b-4409-97df-a53fa2e39d09-S0
[03:36:51]W: [Step 10/10] I0618 03:36:51.460062 2813 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617
[03:36:51]W: [Step 10/10] I0618 03:36:51.562192 2816 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617 after 102.104064ms
[03:36:51]W: [Step 10/10] I0618 03:36:51.563100 2816 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617
[03:36:51]W: [Step 10/10] I0618 03:36:51.564021 2815 cgroups.cpp:1438] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos_test_ecfecccd-6714-4ec7-b5eb-a3071b772617 after 901888ns
[03:36:51] : [Step 10/10] [ FAILED ] MemoryPressureMesosTest.CGROUPS_ROOT_SlaveRecovery (22119 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)